[==========] 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:17:56.625185 13820 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.127.62:39023
I20260812 06:17:56.626358 13820 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:17:56.627080 13820 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:56.634649 13825 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:17:56.634684 13828 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:17:56.634742 13820 server_base.cc:1061] running on GCE node
W20260812 06:17:56.635073 13826 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:56.635682 13820 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:56.635835 13820 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:17:56.635911 13820 hybrid_clock.cc:648] HybridClock initialized: now 1786515476635885 us; error 0 us; skew 500 ppm
I20260812 06:17:56.637966 13820 webserver.cc:533] Webserver started at http://127.13.127.62:38391/ using document root <none> and password file <none>
I20260812 06:17:56.638600 13820 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:56.638712 13820 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:56.639062 13820 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:56.640995 13820 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/master-0-root/instance:
uuid: "98fbe6043e8a4316a5682670dd3e22a0"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-27sr"
I20260812 06:17:56.645241 13820 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.001s	sys 0.003s
I20260812 06:17:56.648061 13835 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:17:56.649370 13820 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:56.649536 13820 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/master-0-root
uuid: "98fbe6043e8a4316a5682670dd3e22a0"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-27sr"
I20260812 06:17:56.649662 13820 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-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:17:56.669153 13820 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:56.669880 13820 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:17:56.670075 13820 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:56.678683 13820 rpc_server.cc:307] RPC server started. Bound to: 127.13.127.62:39023
I20260812 06:17:56.678751 13899 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.127.62:39023 every 8 connection(s)
I20260812 06:17:56.681150 13900 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:17:56.686831 13900 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: Bootstrap starting.
I20260812 06:17:56.689332 13900 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:56.690316 13900 log.cc:826] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:56.692239 13900 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: No bootstrap required, opened a new log
I20260812 06:17:56.695148 13900 raft_consensus.cc:359] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98fbe6043e8a4316a5682670dd3e22a0" member_type: VOTER }
I20260812 06:17:56.695320 13900 raft_consensus.cc:385] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:56.695431 13900 raft_consensus.cc:740] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 98fbe6043e8a4316a5682670dd3e22a0, State: Initialized, Role: FOLLOWER
I20260812 06:17:56.696143 13900 consensus_queue.cc:260] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [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: "98fbe6043e8a4316a5682670dd3e22a0" member_type: VOTER }
I20260812 06:17:56.696295 13900 raft_consensus.cc:399] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:56.696385 13900 raft_consensus.cc:493] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:56.696535 13900 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:56.697418 13900 raft_consensus.cc:515] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98fbe6043e8a4316a5682670dd3e22a0" member_type: VOTER }
I20260812 06:17:56.697889 13900 leader_election.cc:304] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [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: 98fbe6043e8a4316a5682670dd3e22a0; no voters: 
I20260812 06:17:56.698266 13900 leader_election.cc:290] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:56.698428 13903 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:56.698699 13903 raft_consensus.cc:697] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 1 LEADER]: Becoming Leader. State: Replica: 98fbe6043e8a4316a5682670dd3e22a0, State: Running, Role: LEADER
I20260812 06:17:56.699129 13903 consensus_queue.cc:237] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [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: "98fbe6043e8a4316a5682670dd3e22a0" member_type: VOTER }
I20260812 06:17:56.699280 13900 sys_catalog.cc:565] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:56.701362 13904 sys_catalog.cc:455] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "98fbe6043e8a4316a5682670dd3e22a0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98fbe6043e8a4316a5682670dd3e22a0" member_type: VOTER } }
I20260812 06:17:56.701318 13905 sys_catalog.cc:455] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 98fbe6043e8a4316a5682670dd3e22a0. Latest consensus state: current_term: 1 leader_uuid: "98fbe6043e8a4316a5682670dd3e22a0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98fbe6043e8a4316a5682670dd3e22a0" member_type: VOTER } }
I20260812 06:17:56.701457 13904 sys_catalog.cc:458] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:56.701503 13905 sys_catalog.cc:458] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:56.701767 13820 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:56.703773 13921 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:56.703863 13921 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:56.703943 13920 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:56.704663 13920 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:56.709795 13920 catalog_manager.cc:1383] Generated new cluster ID: 993508aad53f49f6a76919b378731cd2
I20260812 06:17:56.709870 13920 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:56.720235 13920 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:56.721392 13920 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:56.729928 13920 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: Generated new TSK 0
I20260812 06:17:56.730723 13920 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:56.734308 13820 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:56.737319 13928 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:17:56.737344 13927 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:17:56.737344 13931 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:17:56.737814 13820 server_base.cc:1061] running on GCE node
I20260812 06:17:56.737993 13820 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:56.738063 13820 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:17:56.738098 13820 hybrid_clock.cc:648] HybridClock initialized: now 1786515476738098 us; error 0 us; skew 500 ppm
I20260812 06:17:56.739126 13820 webserver.cc:533] Webserver started at http://127.13.127.1:33269/ using document root <none> and password file <none>
I20260812 06:17:56.739305 13820 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:56.739380 13820 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:56.739464 13820 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:56.739935 13820 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/instance:
uuid: "b92511ceb9ce4f538e9aa4f16656c4fe"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-27sr"
I20260812 06:17:56.741519 13820 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:56.742612 13937 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:17:56.742873 13820 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:56.742950 13820 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root
uuid: "b92511ceb9ce4f538e9aa4f16656c4fe"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-27sr"
I20260812 06:17:56.743044 13820 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-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:17:56.763090 13820 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:56.763617 13820 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:56.764256 13820 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:56.765201 13820 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:56.765255 13820 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:56.765332 13820 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:56.765372 13820 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:56.772540 13820 rpc_server.cc:307] RPC server started. Bound to: 127.13.127.1:45981
I20260812 06:17:56.772576 14012 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.127.1:45981 every 8 connection(s)
I20260812 06:17:56.783187 14013 heartbeater.cc:344] Connected to a master server at 127.13.127.62:39023
I20260812 06:17:56.783468 14013 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:56.784018 14013 heartbeater.cc:507] Master 127.13.127.62:39023 requested a full tablet report, sending...
I20260812 06:17:56.785601 13856 ts_manager.cc:194] Registered new tserver with Master: b92511ceb9ce4f538e9aa4f16656c4fe (127.13.127.1:45981)
I20260812 06:17:56.785795 13820 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012529442s
I20260812 06:17:56.787235 13856 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58356
I20260812 06:17:56.796132 13856 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58372:
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:17:56.810962 13970 tablet_service.cc:1511] Processing CreateTablet for tablet 63316d13840f4771be1a2e89d6931ba4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e17e26705454439583adfef27aa8e550]), partition=
I20260812 06:17:56.811594 13970 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 63316d13840f4771be1a2e89d6931ba4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:56.814131 14030 tablet_bootstrap.cc:492] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Bootstrap starting.
I20260812 06:17:56.815446 14030 tablet_bootstrap.cc:654] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:56.816932 14030 tablet_bootstrap.cc:492] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: No bootstrap required, opened a new log
I20260812 06:17:56.817061 14030 ts_tablet_manager.cc:1403] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:56.817610 14030 raft_consensus.cc:359] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b92511ceb9ce4f538e9aa4f16656c4fe" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 45981 } }
I20260812 06:17:56.817737 14030 raft_consensus.cc:385] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:56.817763 14030 raft_consensus.cc:740] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b92511ceb9ce4f538e9aa4f16656c4fe, State: Initialized, Role: FOLLOWER
I20260812 06:17:56.817977 14030 consensus_queue.cc:260] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [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: "b92511ceb9ce4f538e9aa4f16656c4fe" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 45981 } }
I20260812 06:17:56.818082 14030 raft_consensus.cc:399] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:56.818162 14030 raft_consensus.cc:493] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:56.818228 14030 raft_consensus.cc:3060] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:56.819397 14030 raft_consensus.cc:515] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b92511ceb9ce4f538e9aa4f16656c4fe" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 45981 } }
I20260812 06:17:56.819533 14030 leader_election.cc:304] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [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: b92511ceb9ce4f538e9aa4f16656c4fe; no voters: 
I20260812 06:17:56.819733 14030 leader_election.cc:290] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:56.819864 14033 raft_consensus.cc:2804] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:56.820089 14033 raft_consensus.cc:697] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 1 LEADER]: Becoming Leader. State: Replica: b92511ceb9ce4f538e9aa4f16656c4fe, State: Running, Role: LEADER
I20260812 06:17:56.820267 14030 ts_tablet_manager.cc:1434] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:56.820245 14033 consensus_queue.cc:237] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [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: "b92511ceb9ce4f538e9aa4f16656c4fe" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 45981 } }
I20260812 06:17:56.820734 14013 heartbeater.cc:499] Master 127.13.127.62:39023 was elected leader, sending a full tablet report...
I20260812 06:17:56.823578 13856 catalog_manager.cc:5719] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe reported cstate change: term changed from 0 to 1, leader changed from <none> to b92511ceb9ce4f538e9aa4f16656c4fe (127.13.127.1). New cstate: current_term: 1 leader_uuid: "b92511ceb9ce4f538e9aa4f16656c4fe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b92511ceb9ce4f538e9aa4f16656c4fe" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 45981 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:56.895323 13820 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.023s	sys 0.006s
I20260812 06:17:57.023746 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushMRSOp(63316d13840f4771be1a2e89d6931ba4): perf score=15.086190
I20260812 06:17:57.187927 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushMRSOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.164s	user 0.127s	sys 0.029s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":316,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1272,"drs_written":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39699,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":171,"threads_started":1,"update_count":1450}
I20260812 06:17:57.189105 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling LogGCOp(63316d13840f4771be1a2e89d6931ba4): free 20743880 bytes of WAL
I20260812 06:17:57.189421 13942 log_reader.cc:385] T 63316d13840f4771be1a2e89d6931ba4: removed 2 log segments from log reader
I20260812 06:17:57.189491 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000001 (ops 1-6)
I20260812 06:17:57.189554 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000002 (ops 7-11)
I20260812 06:17:57.195086 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: LogGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:57.195513 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:57.213416 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6616,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.213884 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4): 12719216 bytes on disk
I20260812 06:17:57.214413 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.214808 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:57.355693 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.141s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":964,"lbm_read_time_us":7737,"lbm_reads_lt_1ms":454,"lbm_write_time_us":27956,"lbm_writes_lt_1ms":433,"mutex_wait_us":282,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":333,"threads_started":5,"update_count":1950}
I20260812 06:17:57.356235 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:57.403663 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18670,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.404191 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:57.414433 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.414989 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:57.548076 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.133s	user 0.094s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":683,"lbm_read_time_us":8625,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26894,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:57.548698 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:57.597968 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.048s	user 0.038s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22474,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.598524 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:57.611580 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.612190 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:57.745918 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.134s	user 0.092s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1395,"lbm_read_time_us":7930,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28236,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:17:57.746595 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:57.803941 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.057s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15341,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.804492 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:57.815333 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.815833 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:57.979552 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.163s	user 0.100s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":11748,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26806,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:57.980270 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:58.025192 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.045s	user 0.023s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19880,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.025722 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:58.037107 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.037756 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:58.168509 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.131s	user 0.120s	sys 0.009s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":618,"lbm_read_time_us":9034,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26809,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:58.169072 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:58.214802 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.046s	user 0.006s	sys 0.037s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20539,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.215332 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:58.231449 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.232342 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:58.363499 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.131s	user 0.096s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1211,"lbm_read_time_us":10050,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26126,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:58.364277 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:58.417575 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.053s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19029,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.418092 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:58.429880 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.430408 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:58.552707 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.122s	user 0.094s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":961,"lbm_read_time_us":9164,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25295,"lbm_writes_lt_1ms":443,"mutex_wait_us":381,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:58.553654 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:58.600200 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.046s	user 0.015s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15110,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.600834 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:58.611871 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.612445 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushMRSOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:58.656531 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushMRSOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.044s	user 0.033s	sys 0.002s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1485,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1446,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:58.657444 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling LogGCOp(63316d13840f4771be1a2e89d6931ba4): free 124257246 bytes of WAL
I20260812 06:17:58.657699 13942 log_reader.cc:385] T 63316d13840f4771be1a2e89d6931ba4: removed 12 log segments from log reader
I20260812 06:17:58.657743 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000003 (ops 12-16)
I20260812 06:17:58.657773 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000004 (ops 17-21)
I20260812 06:17:58.657837 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000005 (ops 22-26)
I20260812 06:17:58.657881 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000006 (ops 27-31)
I20260812 06:17:58.657944 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000007 (ops 32-36)
I20260812 06:17:58.657984 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000008 (ops 37-41)
I20260812 06:17:58.658023 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000009 (ops 42-46)
I20260812 06:17:58.658058 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000010 (ops 47-51)
I20260812 06:17:58.658095 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000011 (ops 52-56)
I20260812 06:17:58.658142 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000012 (ops 57-60)
I20260812 06:17:58.658183 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000013 (ops 61-65)
I20260812 06:17:58.658222 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000014 (ops 66-70)
I20260812 06:17:58.687881 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: LogGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.030s	user 0.002s	sys 0.028s Metrics: {}
I20260812 06:17:58.688476 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4): 482 bytes on disk
I20260812 06:17:58.690291 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.691133 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=3.181125
I20260812 06:17:58.710664 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.019s	user 0.011s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5993,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:58.711350 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:58.729526 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6711,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.730052 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:58.945705 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.215s	user 0.166s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":946,"lbm_read_time_us":14868,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35698,"lbm_writes_lt_1ms":643,"mutex_wait_us":310,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":98,"threads_started":1,"update_count":3000}
I20260812 06:17:58.949369 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=14.095187
I20260812 06:17:59.002122 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.052s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22345,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.002707 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:59.161360 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.158s	user 0.126s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":875,"lbm_read_time_us":12538,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23972,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:17:59.162241 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=11.118625
I20260812 06:17:59.199980 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.038s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16483,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:59.200845 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:59.220010 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6264,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.220559 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:59.357760 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.137s	user 0.116s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":750,"lbm_read_time_us":8940,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27015,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:59.358445 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:59.401382 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.043s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15496,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.401995 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:59.413148 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.413671 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:59.553709 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.140s	user 0.104s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":714,"lbm_read_time_us":9245,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27731,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:59.554513 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:59.604782 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.050s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16540,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.605420 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:59.618811 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4584,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.619349 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:59.744578 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.125s	user 0.107s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"lbm_read_time_us":9924,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24373,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:17:59.745275 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:59.788417 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.043s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16597,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.788976 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:59.805871 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6335,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.806465 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:17:59.952526 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.146s	user 0.114s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":588,"lbm_read_time_us":11244,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24585,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:59.953903 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:17:59.987490 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.033s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14591,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.988097 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:17:59.998571 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.999183 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:00.128708 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.129s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":8273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25978,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":72064,"update_count":2000}
I20260812 06:18:00.129436 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:18:00.172034 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.042s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17425,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.172545 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:00.183948 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4433,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.184737 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushMRSOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:00.216609 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushMRSOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.032s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1769,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:00.217337 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling LogGCOp(63316d13840f4771be1a2e89d6931ba4): free 129320468 bytes of WAL
I20260812 06:18:00.217571 13942 log_reader.cc:385] T 63316d13840f4771be1a2e89d6931ba4: removed 13 log segments from log reader
I20260812 06:18:00.217612 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000015 (ops 71-75)
I20260812 06:18:00.217664 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000016 (ops 76-80)
I20260812 06:18:00.217710 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000017 (ops 81-85)
I20260812 06:18:00.217752 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000018 (ops 86-90)
I20260812 06:18:00.217798 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000019 (ops 91-95)
I20260812 06:18:00.217839 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000020 (ops 96-100)
I20260812 06:18:00.217878 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000021 (ops 101-104)
I20260812 06:18:00.217921 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000022 (ops 105-109)
I20260812 06:18:00.217962 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000023 (ops 110-114)
I20260812 06:18:00.218000 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000024 (ops 115-118)
I20260812 06:18:00.218040 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000025 (ops 119-123)
I20260812 06:18:00.218078 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000026 (ops 124-128)
I20260812 06:18:00.218118 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000027 (ops 129-133)
I20260812 06:18:00.247808 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: LogGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:00.248416 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4): 473 bytes on disk
I20260812 06:18:00.248880 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.249539 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=6.157687
I20260812 06:18:00.272747 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.023s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":9600,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:00.273239 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:00.452237 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.179s	user 0.111s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":938,"lbm_read_time_us":13114,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34360,"lbm_writes_lt_1ms":643,"mutex_wait_us":684,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:18:00.453096 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=14.095187
I20260812 06:18:00.506138 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.053s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23326,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.506633 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:00.518980 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.519430 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:00.676748 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.157s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":11599,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31236,"lbm_writes_lt_1ms":543,"mutex_wait_us":122,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:00.677836 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=11.118625
I20260812 06:18:00.711493 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.033s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14511,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.712334 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:00.728322 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.728870 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:00.874961 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.146s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1269,"lbm_read_time_us":8418,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29166,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:18:00.875880 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=11.118625
I20260812 06:18:00.918823 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.043s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18908,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:00.919423 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:00.931385 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4349,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.932085 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:01.074559 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.142s	user 0.115s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":13567,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":27811,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:18:01.075112 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:18:01.125962 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.051s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18072,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.126722 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:01.138078 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4363,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.138602 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:01.305585 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":965,"lbm_read_time_us":11881,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29507,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:01.306270 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:18:01.353940 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.047s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15804,"lbm_writes_lt_1ms":303,"mutex_wait_us":3,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.354568 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:01.366962 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.367771 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:01.514241 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.146s	user 0.121s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":106,"lbm_read_time_us":11531,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28043,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":2000}
I20260812 06:18:01.515087 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:18:01.550638 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15242,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.551327 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=2.188937
I20260812 06:18:01.563674 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4708,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.564297 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:01.709272 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.145s	user 0.118s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":9195,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29046,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:01.709759 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=10.126437
I20260812 06:18:01.742542 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.033s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13985,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.743297 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushMRSOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:01.773047 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushMRSOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.030s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1407,"drs_written":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4,"lbm_write_time_us":4244,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:01.773998 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling LogGCOp(63316d13840f4771be1a2e89d6931ba4): free 124710614 bytes of WAL
I20260812 06:18:01.774334 13942 log_reader.cc:385] T 63316d13840f4771be1a2e89d6931ba4: removed 12 log segments from log reader
I20260812 06:18:01.774461 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000028 (ops 134-138)
I20260812 06:18:01.774569 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000029 (ops 139-143)
I20260812 06:18:01.774680 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000030 (ops 144-148)
I20260812 06:18:01.774740 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000031 (ops 149-153)
I20260812 06:18:01.774766 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000032 (ops 154-158)
I20260812 06:18:01.774834 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000033 (ops 159-163)
I20260812 06:18:01.774873 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000034 (ops 164-168)
I20260812 06:18:01.774936 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000035 (ops 169-173)
I20260812 06:18:01.774974 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000036 (ops 174-178)
I20260812 06:18:01.775064 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000037 (ops 179-183)
I20260812 06:18:01.775126 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000038 (ops 184-188)
I20260812 06:18:01.775161 13942 log.cc:1079] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/63316d13840f4771be1a2e89d6931ba4/wal-000000039 (ops 189-193)
I20260812 06:18:01.805859 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: LogGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:01.806371 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=6.157687
I20260812 06:18:01.828538 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.022s	user 0.012s	sys 0.009s Metrics: {"bytes_written":8040983,"delete_count":0,"lbm_write_time_us":9184,"lbm_writes_lt_1ms":199,"reinsert_count":0,"update_count":980}
I20260812 06:18:01.829048 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4): 472 bytes on disk
I20260812 06:18:01.829946 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: UndoDeltaBlockGCOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.830731 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:01.963524 13820 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.068s	user 1.913s	sys 0.104s
I20260812 06:18:01.998374 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.167s	user 0.114s	sys 0.051s Metrics: {"cfile_cache_miss":528,"cfile_cache_miss_bytes":24610595,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":13344,"lbm_reads_lt_1ms":556,"lbm_write_time_us":29802,"lbm_writes_lt_1ms":539,"peak_mem_usage":61911376,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2480}
I20260812 06:18:01.998927 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4): perf score=11.118625
I20260812 06:18:02.026059 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: FlushDeltaMemStoresOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.027s	user 0.016s	sys 0.009s Metrics: {"bytes_written":12471590,"delete_count":0,"lbm_write_time_us":11863,"lbm_writes_lt_1ms":307,"reinsert_count":0,"update_count":1520}
I20260812 06:18:02.026770 14014 maintenance_manager.cc:419] P b92511ceb9ce4f538e9aa4f16656c4fe: Scheduling MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4): perf score=1.000000
I20260812 06:18:02.045662 13820 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.004s	sys 0.000s
I20260812 06:18:02.046512 13820 tablet_server.cc:179] TabletServer@127.13.127.1:0 shutting down...
I20260812 06:18:02.136723 13942 maintenance_manager.cc:643] P b92511ceb9ce4f538e9aa4f16656c4fe: MajorDeltaCompactionOp(63316d13840f4771be1a2e89d6931ba4) complete. Timing: real 0.110s	user 0.085s	sys 0.024s Metrics: {"cfile_cache_miss":335,"cfile_cache_miss_bytes":16733846,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":400,"lbm_read_time_us":11218,"lbm_reads_lt_1ms":371,"lbm_write_time_us":16958,"lbm_writes_lt_1ms":347,"mutex_wait_us":60,"peak_mem_usage":38426896,"reinsert_count":0,"update_count":1520}
I20260812 06:18:02.137530 13820 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:02.137976 13820 tablet_replica.cc:333] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe: stopping tablet replica
I20260812 06:18:02.138237 13820 raft_consensus.cc:2243] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:02.138494 13820 raft_consensus.cc:2272] T 63316d13840f4771be1a2e89d6931ba4 P b92511ceb9ce4f538e9aa4f16656c4fe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:02.154630 13820 tablet_server.cc:196] TabletServer@127.13.127.1:0 shutdown complete.
I20260812 06:18:02.168736 13820 master.cc:562] Master@127.13.127.62:39023 shutting down...
I20260812 06:18:02.173095 13820 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:02.173312 13820 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:02.173400 13820 tablet_replica.cc:333] T 00000000000000000000000000000000 P 98fbe6043e8a4316a5682670dd3e22a0: stopping tablet replica
I20260812 06:18:02.185818 13820 master.cc:584] Master@127.13.127.62:39023 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5662 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:02.286666 13820 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.127.62:35353
I20260812 06:18:02.287129 13820 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:02.289572 13820 server_base.cc:1061] running on GCE node
W20260812 06:18:02.289695 14055 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:02.289634 14053 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:02.289634 14052 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.290097 13820 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.290162 13820 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:02.290190 13820 hybrid_clock.cc:648] HybridClock initialized: now 1786515482290190 us; error 0 us; skew 500 ppm
I20260812 06:18:02.291134 13820 webserver.cc:533] Webserver started at http://127.13.127.62:43179/ using document root <none> and password file <none>
I20260812 06:18:02.291379 13820 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.291458 13820 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.291548 13820 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.292132 13820 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/master-0-root/instance:
uuid: "8239632bc01c455298d762a5c928391d"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-27sr"
I20260812 06:18:02.293989 13820 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:02.295102 14061 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.295434 13820 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:02.295538 13820 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/master-0-root
uuid: "8239632bc01c455298d762a5c928391d"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-27sr"
I20260812 06:18:02.295632 13820 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:02.311486 13820 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:02.311997 13820 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:02.316397 13820 rpc_server.cc:307] RPC server started. Bound to: 127.13.127.62:35353
I20260812 06:18:02.318639 14122 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.127.62:35353 every 8 connection(s)
I20260812 06:18:02.319766 14124 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:02.331874 14124 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d: Bootstrap starting.
I20260812 06:18:02.332865 14124 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:02.334054 14124 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d: No bootstrap required, opened a new log
I20260812 06:18:02.334496 14124 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8239632bc01c455298d762a5c928391d" member_type: VOTER }
I20260812 06:18:02.334609 14124 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:02.334676 14124 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8239632bc01c455298d762a5c928391d, State: Initialized, Role: FOLLOWER
I20260812 06:18:02.334851 14124 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [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: "8239632bc01c455298d762a5c928391d" member_type: VOTER }
I20260812 06:18:02.334941 14124 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:02.334985 14124 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:02.335041 14124 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:02.335783 14124 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8239632bc01c455298d762a5c928391d" member_type: VOTER }
I20260812 06:18:02.335968 14124 leader_election.cc:304] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [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: 8239632bc01c455298d762a5c928391d; no voters: 
I20260812 06:18:02.336194 14124 leader_election.cc:290] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:02.336386 14128 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:02.336651 14128 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 1 LEADER]: Becoming Leader. State: Replica: 8239632bc01c455298d762a5c928391d, State: Running, Role: LEADER
I20260812 06:18:02.336776 14124 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:02.336825 14128 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [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: "8239632bc01c455298d762a5c928391d" member_type: VOTER }
I20260812 06:18:02.337306 14129 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8239632bc01c455298d762a5c928391d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8239632bc01c455298d762a5c928391d" member_type: VOTER } }
I20260812 06:18:02.337430 14129 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:02.337329 14132 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8239632bc01c455298d762a5c928391d. Latest consensus state: current_term: 1 leader_uuid: "8239632bc01c455298d762a5c928391d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8239632bc01c455298d762a5c928391d" member_type: VOTER } }
I20260812 06:18:02.337543 14132 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:02.337821 14139 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:02.338651 14139 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:02.338855 13820 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:02.340809 14139 catalog_manager.cc:1383] Generated new cluster ID: b9b443a518d6401d9615612856ae0ea3
I20260812 06:18:02.340884 14139 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:02.348744 14139 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:02.349465 14139 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:02.363369 14139 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d: Generated new TSK 0
I20260812 06:18:02.363562 14139 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:02.371276 13820 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:02.373724 14155 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.373865 13820 server_base.cc:1061] running on GCE node
W20260812 06:18:02.373724 14158 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:02.373870 14156 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.374234 13820 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.374277 13820 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:02.374293 13820 hybrid_clock.cc:648] HybridClock initialized: now 1786515482374293 us; error 0 us; skew 500 ppm
I20260812 06:18:02.375276 13820 webserver.cc:533] Webserver started at http://127.13.127.1:39533/ using document root <none> and password file <none>
I20260812 06:18:02.375504 13820 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.375583 13820 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.375676 13820 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.376209 13820 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/instance:
uuid: "a70975942a15480dbde76a22686c4fbd"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-27sr"
I20260812 06:18:02.377871 13820 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:02.378942 14164 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.379254 13820 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:02.379333 13820 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root
uuid: "a70975942a15480dbde76a22686c4fbd"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-27sr"
I20260812 06:18:02.379437 13820 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:02.390733 13820 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:02.391148 13820 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:02.391486 13820 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:02.392087 13820 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:02.392130 13820 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.392211 13820 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:02.392252 13820 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.396981 13820 rpc_server.cc:307] RPC server started. Bound to: 127.13.127.1:43147
I20260812 06:18:02.397037 14247 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.127.1:43147 every 8 connection(s)
I20260812 06:18:02.409631 14248 heartbeater.cc:344] Connected to a master server at 127.13.127.62:35353
I20260812 06:18:02.409843 14248 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:02.410096 14248 heartbeater.cc:507] Master 127.13.127.62:35353 requested a full tablet report, sending...
I20260812 06:18:02.410835 14081 ts_manager.cc:194] Registered new tserver with Master: a70975942a15480dbde76a22686c4fbd (127.13.127.1:43147)
I20260812 06:18:02.410957 13820 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013467354s
I20260812 06:18:02.411933 14081 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50976
I20260812 06:18:02.418886 14081 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50990:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:02.429056 14203 tablet_service.cc:1511] Processing CreateTablet for tablet 1271b31102e342f5baba08c6e4ddb30a (DEFAULT_TABLE table=heavy-update-compaction-test [id=3fac7962ea7d48eeafa73837e17d5128]), partition=
I20260812 06:18:02.429399 14203 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1271b31102e342f5baba08c6e4ddb30a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:02.431830 14263 tablet_bootstrap.cc:492] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Bootstrap starting.
I20260812 06:18:02.432937 14263 tablet_bootstrap.cc:654] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:02.434271 14263 tablet_bootstrap.cc:492] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: No bootstrap required, opened a new log
I20260812 06:18:02.434399 14263 ts_tablet_manager.cc:1403] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:02.434968 14263 raft_consensus.cc:359] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a70975942a15480dbde76a22686c4fbd" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 43147 } }
I20260812 06:18:02.435097 14263 raft_consensus.cc:385] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:02.435151 14263 raft_consensus.cc:740] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a70975942a15480dbde76a22686c4fbd, State: Initialized, Role: FOLLOWER
I20260812 06:18:02.435314 14263 consensus_queue.cc:260] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [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: "a70975942a15480dbde76a22686c4fbd" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 43147 } }
I20260812 06:18:02.435413 14263 raft_consensus.cc:399] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:02.435468 14263 raft_consensus.cc:493] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:02.435532 14263 raft_consensus.cc:3060] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:02.436443 14263 raft_consensus.cc:515] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a70975942a15480dbde76a22686c4fbd" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 43147 } }
I20260812 06:18:02.436632 14263 leader_election.cc:304] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [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: a70975942a15480dbde76a22686c4fbd; no voters: 
I20260812 06:18:02.436878 14263 leader_election.cc:290] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:02.437027 14265 raft_consensus.cc:2804] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:02.437268 14263 ts_tablet_manager.cc:1434] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:02.437362 14248 heartbeater.cc:499] Master 127.13.127.62:35353 was elected leader, sending a full tablet report...
I20260812 06:18:02.437340 14265 raft_consensus.cc:697] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 1 LEADER]: Becoming Leader. State: Replica: a70975942a15480dbde76a22686c4fbd, State: Running, Role: LEADER
I20260812 06:18:02.437553 14265 consensus_queue.cc:237] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [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: "a70975942a15480dbde76a22686c4fbd" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 43147 } }
I20260812 06:18:02.439093 14081 catalog_manager.cc:5719] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd reported cstate change: term changed from 0 to 1, leader changed from <none> to a70975942a15480dbde76a22686c4fbd (127.13.127.1). New cstate: current_term: 1 leader_uuid: "a70975942a15480dbde76a22686c4fbd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a70975942a15480dbde76a22686c4fbd" member_type: VOTER last_known_addr { host: "127.13.127.1" port: 43147 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:02.499478 13820 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.010s
I20260812 06:18:02.648061 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a): perf score=19.054940
I20260812 06:18:02.803862 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.155s	user 0.127s	sys 0.024s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":853,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40695,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:02.804551 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling LogGCOp(1271b31102e342f5baba08c6e4ddb30a): free 20743880 bytes of WAL
I20260812 06:18:02.804814 14169 log_reader.cc:385] T 1271b31102e342f5baba08c6e4ddb30a: removed 2 log segments from log reader
I20260812 06:18:02.804860 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000001 (ops 1-6)
I20260812 06:18:02.804893 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000002 (ops 7-11)
I20260812 06:18:02.809729 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: LogGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:02.810156 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a): 16411392 bytes on disk
I20260812 06:18:02.810611 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.811039 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:02.825603 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.826179 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:02.977597 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.151s	user 0.111s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":953,"lbm_read_time_us":10935,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25902,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":371,"threads_started":5,"update_count":2000}
I20260812 06:18:02.978164 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:03.036033 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.058s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26742,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.036556 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:03.048573 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.049119 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:03.215498 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.166s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":11440,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29459,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":78336,"update_count":2500}
I20260812 06:18:03.216173 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:03.282837 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.066s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20917,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.283360 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:03.294750 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.295220 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:03.475188 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.180s	user 0.117s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":13955,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30935,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:18:03.475874 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:03.561815 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.086s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":49751,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.562471 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:03.573654 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.574101 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:03.749701 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.175s	user 0.135s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1047,"lbm_read_time_us":12598,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29527,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:18:03.750344 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:03.814252 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.064s	user 0.027s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22549,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.814817 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:03.826073 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.826758 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:04.019032 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.192s	user 0.136s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1123,"lbm_read_time_us":13199,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30981,"lbm_writes_lt_1ms":543,"mutex_wait_us":427,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":78080,"update_count":2500}
I20260812 06:18:04.019718 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:04.072072 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.052s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23294,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.072638 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:04.099632 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.027s	user 0.012s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.100324 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:04.138767 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.038s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1630,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1744,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:04.139405 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling LogGCOp(1271b31102e342f5baba08c6e4ddb30a): free 120553325 bytes of WAL
I20260812 06:18:04.139644 14169 log_reader.cc:385] T 1271b31102e342f5baba08c6e4ddb30a: removed 12 log segments from log reader
I20260812 06:18:04.139701 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000003 (ops 12-16)
I20260812 06:18:04.139763 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000004 (ops 17-21)
I20260812 06:18:04.139817 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000005 (ops 22-26)
I20260812 06:18:04.139858 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000006 (ops 27-30)
I20260812 06:18:04.139921 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000007 (ops 31-35)
I20260812 06:18:04.139968 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000008 (ops 36-40)
I20260812 06:18:04.139994 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000009 (ops 41-45)
I20260812 06:18:04.140033 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000010 (ops 46-50)
I20260812 06:18:04.140071 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000011 (ops 51-54)
I20260812 06:18:04.140110 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000012 (ops 55-59)
I20260812 06:18:04.140151 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000013 (ops 60-64)
I20260812 06:18:04.140187 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000014 (ops 65-69)
I20260812 06:18:04.167450 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: LogGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:18:04.168226 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a): 462 bytes on disk
I20260812 06:18:04.168764 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.169335 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=3.181125
I20260812 06:18:04.186055 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.017s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:04.186591 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:04.197247 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3782,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.197816 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:04.459883 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.262s	user 0.153s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2340,"lbm_read_time_us":17242,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42322,"lbm_writes_lt_1ms":743,"mutex_wait_us":382,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:18:04.460788 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=18.063937
I20260812 06:18:04.527658 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.067s	user 0.043s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28246,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:04.528167 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:04.539718 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.540333 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:04.759528 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.219s	user 0.150s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1228,"lbm_read_time_us":14454,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36143,"lbm_writes_lt_1ms":643,"mutex_wait_us":408,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":82944,"update_count":3000}
I20260812 06:18:04.760545 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:04.814343 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.054s	user 0.044s	sys 0.004s Metrics: {"bytes_written":16409940,"delete_count":0,"lbm_write_time_us":21828,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.815162 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:04.823511 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.008s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1395006,"delete_count":0,"lbm_write_time_us":1552,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:18:04.824025 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.196750
I20260812 06:18:04.831670 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.007s	user 0.001s	sys 0.005s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":2821,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:04.832177 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:05.028656 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.196s	user 0.144s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":788,"lbm_read_time_us":13096,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32361,"lbm_writes_lt_1ms":543,"mutex_wait_us":92,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:18:05.029247 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:05.091775 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.062s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28218,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.092365 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:05.103566 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.104310 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:05.308382 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.203s	user 0.132s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":13910,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34470,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:05.309137 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:05.372596 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.063s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25301,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.373180 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:05.384497 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.385025 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:05.582923 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.198s	user 0.131s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":507,"lbm_read_time_us":13810,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32272,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:05.583523 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:05.643308 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.060s	user 0.043s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23993,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.643821 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:05.664230 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.020s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.664877 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:05.703648 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.039s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1445,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1960,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:05.704378 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling LogGCOp(1271b31102e342f5baba08c6e4ddb30a): free 112239374 bytes of WAL
I20260812 06:18:05.704668 14169 log_reader.cc:385] T 1271b31102e342f5baba08c6e4ddb30a: removed 11 log segments from log reader
I20260812 06:18:05.704747 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000015 (ops 70-74)
I20260812 06:18:05.704800 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000016 (ops 75-79)
I20260812 06:18:05.704866 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000017 (ops 80-84)
I20260812 06:18:05.704892 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000018 (ops 85-88)
I20260812 06:18:05.704928 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000019 (ops 89-93)
I20260812 06:18:05.704967 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000020 (ops 94-98)
I20260812 06:18:05.705003 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000021 (ops 99-103)
I20260812 06:18:05.705036 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000022 (ops 104-108)
I20260812 06:18:05.705068 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000023 (ops 109-113)
I20260812 06:18:05.705101 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000024 (ops 114-118)
I20260812 06:18:05.705128 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000025 (ops 119-123)
I20260812 06:18:05.737802 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: LogGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.033s	user 0.001s	sys 0.032s Metrics: {}
I20260812 06:18:05.738401 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:05.757579 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.758211 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a): 447 bytes on disk
I20260812 06:18:05.758746 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.759416 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:05.982575 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.223s	user 0.139s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1107,"lbm_read_time_us":16517,"lbm_reads_lt_1ms":665,"lbm_write_time_us":38218,"lbm_writes_lt_1ms":643,"mutex_wait_us":335,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:05.983388 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:06.036962 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.053s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23260,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.037645 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:06.051566 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.052062 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:06.232158 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.180s	user 0.117s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":12697,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30284,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:18:06.232975 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:06.295236 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.062s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20316,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.295840 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:06.307284 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.307757 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:06.498149 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.190s	user 0.142s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1232,"lbm_read_time_us":13574,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31979,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:06.499075 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=11.118625
I20260812 06:18:06.549582 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.050s	user 0.021s	sys 0.027s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21167,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.550094 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:06.576889 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.027s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.577411 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:06.587558 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3926,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.588147 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:06.765900 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.178s	user 0.112s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":428,"lbm_read_time_us":13399,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29515,"lbm_writes_lt_1ms":543,"mutex_wait_us":105,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:18:06.766492 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=11.118625
I20260812 06:18:06.803646 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.037s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15126,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.804426 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:06.828847 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.024s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4876,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.829308 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:06.840610 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.841399 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:07.043078 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.201s	user 0.144s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":345,"lbm_read_time_us":13073,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33989,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":50176,"update_count":2500}
I20260812 06:18:07.044077 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:07.099324 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.055s	user 0.031s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22829,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.099984 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:07.115464 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.116123 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:07.281970 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.166s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":631,"lbm_read_time_us":9744,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29637,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:07.282537 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=14.095187
I20260812 06:18:07.342093 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.059s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23356,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.342618 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:07.354334 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.354848 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:07.381886 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushMRSOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.027s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1699,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1647,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:07.382795 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling LogGCOp(1271b31102e342f5baba08c6e4ddb30a): free 132571568 bytes of WAL
I20260812 06:18:07.383064 14169 log_reader.cc:385] T 1271b31102e342f5baba08c6e4ddb30a: removed 13 log segments from log reader
I20260812 06:18:07.383131 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000026 (ops 124-128)
I20260812 06:18:07.383169 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000027 (ops 129-133)
I20260812 06:18:07.383195 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000028 (ops 134-138)
I20260812 06:18:07.383221 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000029 (ops 139-142)
I20260812 06:18:07.383245 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000030 (ops 143-147)
I20260812 06:18:07.383267 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000031 (ops 148-152)
I20260812 06:18:07.383291 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000032 (ops 153-157)
I20260812 06:18:07.383315 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000033 (ops 158-162)
I20260812 06:18:07.383345 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000034 (ops 163-167)
I20260812 06:18:07.383370 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000035 (ops 168-172)
I20260812 06:18:07.383404 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000036 (ops 173-176)
I20260812 06:18:07.383427 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000037 (ops 177-181)
I20260812 06:18:07.383455 14169 log.cc:1079] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: Deleting log segment in path: /tmp/dist-test-taskoIaq2g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476613229-13820-0/minicluster-data/ts-0-root/wals/1271b31102e342f5baba08c6e4ddb30a/wal-000000038 (ops 182-186)
I20260812 06:18:07.414100 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: LogGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:07.414680 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:07.446581 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.032s	user 0.007s	sys 0.017s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.447193 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a): 483 bytes on disk
I20260812 06:18:07.447674 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: UndoDeltaBlockGCOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.448287 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:07.460314 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.460762 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:07.692955 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.232s	user 0.144s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":777,"lbm_read_time_us":16177,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39964,"lbm_writes_lt_1ms":743,"mutex_wait_us":57,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:07.694689 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=15.087375
I20260812 06:18:07.756349 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.061s	user 0.049s	sys 0.012s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":26554,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:07.756917 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:07.780484 13820 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.281s	user 1.923s	sys 0.209s
I20260812 06:18:07.782258 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.025s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5320,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.782922 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a): perf score=2.188937
I20260812 06:18:07.795430 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: FlushDeltaMemStoresOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":500}
I20260812 06:18:07.796337 14249 maintenance_manager.cc:419] P a70975942a15480dbde76a22686c4fbd: Scheduling MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a): perf score=1.000000
I20260812 06:18:07.862427 13820 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.000s	sys 0.000s
I20260812 06:18:07.863076 13820 tablet_server.cc:179] TabletServer@127.13.127.1:0 shutting down...
I20260812 06:18:07.951829 14169 maintenance_manager.cc:643] P a70975942a15480dbde76a22686c4fbd: MajorDeltaCompactionOp(1271b31102e342f5baba08c6e4ddb30a) complete. Timing: real 0.155s	user 0.097s	sys 0.057s Metrics: {"cfile_cache_hit":262,"cfile_cache_hit_bytes":10669645,"cfile_cache_miss":371,"cfile_cache_miss_bytes":18207560,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":362,"lbm_read_time_us":9063,"lbm_reads_lt_1ms":403,"lbm_write_time_us":31044,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":3000}
I20260812 06:18:07.952880 13820 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:07.953188 13820 tablet_replica.cc:333] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd: stopping tablet replica
I20260812 06:18:07.953349 13820 raft_consensus.cc:2243] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.953568 13820 raft_consensus.cc:2272] T 1271b31102e342f5baba08c6e4ddb30a P a70975942a15480dbde76a22686c4fbd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.968297 13820 tablet_server.cc:196] TabletServer@127.13.127.1:0 shutdown complete.
I20260812 06:18:08.006109 13820 master.cc:562] Master@127.13.127.62:35353 shutting down...
I20260812 06:18:08.010463 13820 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.010710 13820 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.010802 13820 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8239632bc01c455298d762a5c928391d: stopping tablet replica
I20260812 06:18:08.023607 13820 master.cc:584] Master@127.13.127.62:35353 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5832 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11496 ms total)

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