[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:37.829648  7441 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.68.126:41207
I20260812 06:18:37.830622  7441 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:37.831218  7441 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:37.837580  7448 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:37.837600  7451 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:37.837878  7441 server_base.cc:1061] running on GCE node
W20260812 06:18:37.837971  7447 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:37.838429  7441 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:37.838521  7441 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:37.838552  7441 hybrid_clock.cc:648] HybridClock initialized: now 1786515517838550 us; error 0 us; skew 500 ppm
I20260812 06:18:37.840327  7441 webserver.cc:533] Webserver started at http://127.7.68.126:44989/ using document root <none> and password file <none>
I20260812 06:18:37.840857  7441 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:37.840921  7441 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:37.841120  7441 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:37.842689  7441 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/master-0-root/instance:
uuid: "2c95bfb8d85547d58a240939fbe1f13c"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-5k54"
I20260812 06:18:37.846105  7441 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:37.848063  7456 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:37.849026  7441 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:37.849123  7441 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/master-0-root
uuid: "2c95bfb8d85547d58a240939fbe1f13c"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-5k54"
I20260812 06:18:37.849251  7441 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-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:37.867573  7441 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:37.868219  7441 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:37.868403  7441 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:37.876286  7441 rpc_server.cc:307] RPC server started. Bound to: 127.7.68.126:41207
I20260812 06:18:37.876295  7514 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.68.126:41207 every 8 connection(s)
I20260812 06:18:37.878468  7516 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:37.884109  7516 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: Bootstrap starting.
I20260812 06:18:37.886356  7516 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:37.887229  7516 log.cc:826] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:37.888863  7516 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: No bootstrap required, opened a new log
I20260812 06:18:37.891476  7516 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c95bfb8d85547d58a240939fbe1f13c" member_type: VOTER }
I20260812 06:18:37.891666  7516 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:37.891767  7516 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2c95bfb8d85547d58a240939fbe1f13c, State: Initialized, Role: FOLLOWER
I20260812 06:18:37.892311  7516 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [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: "2c95bfb8d85547d58a240939fbe1f13c" member_type: VOTER }
I20260812 06:18:37.892488  7516 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:37.892570  7516 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:37.892707  7516 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:37.893438  7516 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c95bfb8d85547d58a240939fbe1f13c" member_type: VOTER }
I20260812 06:18:37.893852  7516 leader_election.cc:304] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [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: 2c95bfb8d85547d58a240939fbe1f13c; no voters: 
I20260812 06:18:37.894151  7516 leader_election.cc:290] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:37.894280  7520 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:37.894570  7520 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 1 LEADER]: Becoming Leader. State: Replica: 2c95bfb8d85547d58a240939fbe1f13c, State: Running, Role: LEADER
I20260812 06:18:37.895032  7520 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [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: "2c95bfb8d85547d58a240939fbe1f13c" member_type: VOTER }
I20260812 06:18:37.895102  7516 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:37.897109  7522 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2c95bfb8d85547d58a240939fbe1f13c. Latest consensus state: current_term: 1 leader_uuid: "2c95bfb8d85547d58a240939fbe1f13c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c95bfb8d85547d58a240939fbe1f13c" member_type: VOTER } }
I20260812 06:18:37.897140  7521 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2c95bfb8d85547d58a240939fbe1f13c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c95bfb8d85547d58a240939fbe1f13c" member_type: VOTER } }
I20260812 06:18:37.897251  7521 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:37.897253  7522 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:37.897543  7441 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:37.899230  7537 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:37.899291  7537 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:37.899379  7535 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:37.900144  7535 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:37.904570  7535 catalog_manager.cc:1383] Generated new cluster ID: bb9efe4545b04afd8d7aa55e1bee664d
I20260812 06:18:37.904631  7535 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:37.915550  7535 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:37.916587  7535 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:37.937490  7535 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: Generated new TSK 0
I20260812 06:18:37.938159  7535 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:37.962306  7441 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:37.965178  7541 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:37.965284  7545 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:37.965240  7542 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:37.965476  7441 server_base.cc:1061] running on GCE node
I20260812 06:18:37.965633  7441 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:37.965683  7441 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:37.965706  7441 hybrid_clock.cc:648] HybridClock initialized: now 1786515517965706 us; error 0 us; skew 500 ppm
I20260812 06:18:37.966660  7441 webserver.cc:533] Webserver started at http://127.7.68.65:44873/ using document root <none> and password file <none>
I20260812 06:18:37.966825  7441 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:37.966892  7441 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:37.966964  7441 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:37.967388  7441 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/instance:
uuid: "2ce5806569f84f7db0d8a7d509ecf91f"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-5k54"
I20260812 06:18:37.969225  7441 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:37.970309  7550 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:37.970623  7441 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:37.970686  7441 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root
uuid: "2ce5806569f84f7db0d8a7d509ecf91f"
format_stamp: "Formatted at 2026-08-12 06:18:37 on dist-test-slave-5k54"
I20260812 06:18:37.970772  7441 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-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:38.008564  7441 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.009037  7441 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.009533  7441 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:38.010427  7441 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:38.010479  7441 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.010521  7441 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:38.010574  7441 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.017198  7441 rpc_server.cc:307] RPC server started. Bound to: 127.7.68.65:37599
I20260812 06:18:38.017232  7625 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.68.65:37599 every 8 connection(s)
I20260812 06:18:38.030550  7626 heartbeater.cc:344] Connected to a master server at 127.7.68.126:41207
I20260812 06:18:38.030799  7626 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:38.031268  7626 heartbeater.cc:507] Master 127.7.68.126:41207 requested a full tablet report, sending...
I20260812 06:18:38.032845  7475 ts_manager.cc:194] Registered new tserver with Master: 2ce5806569f84f7db0d8a7d509ecf91f (127.7.68.65:37599)
I20260812 06:18:38.033435  7441 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015612167s
I20260812 06:18:38.034397  7475 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47658
I20260812 06:18:38.043292  7475 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47674:
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:38.058395  7583 tablet_service.cc:1511] Processing CreateTablet for tablet 38049fdbd876468f8e77d0f7c00611c9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4e3a6b30751348aabc8897a417f39b6b]), partition=
I20260812 06:18:38.058872  7583 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 38049fdbd876468f8e77d0f7c00611c9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:38.061010  7638 tablet_bootstrap.cc:492] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Bootstrap starting.
I20260812 06:18:38.062254  7638 tablet_bootstrap.cc:654] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.063405  7638 tablet_bootstrap.cc:492] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: No bootstrap required, opened a new log
I20260812 06:18:38.063565  7638 ts_tablet_manager.cc:1403] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:38.064025  7638 raft_consensus.cc:359] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ce5806569f84f7db0d8a7d509ecf91f" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 37599 } }
I20260812 06:18:38.064149  7638 raft_consensus.cc:385] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.064198  7638 raft_consensus.cc:740] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2ce5806569f84f7db0d8a7d509ecf91f, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.064335  7638 consensus_queue.cc:260] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [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: "2ce5806569f84f7db0d8a7d509ecf91f" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 37599 } }
I20260812 06:18:38.064428  7638 raft_consensus.cc:399] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.064476  7638 raft_consensus.cc:493] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.064530  7638 raft_consensus.cc:3060] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.065369  7638 raft_consensus.cc:515] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ce5806569f84f7db0d8a7d509ecf91f" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 37599 } }
I20260812 06:18:38.065543  7638 leader_election.cc:304] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [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: 2ce5806569f84f7db0d8a7d509ecf91f; no voters: 
I20260812 06:18:38.065783  7638 leader_election.cc:290] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.065900  7640 raft_consensus.cc:2804] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.066133  7640 raft_consensus.cc:697] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 1 LEADER]: Becoming Leader. State: Replica: 2ce5806569f84f7db0d8a7d509ecf91f, State: Running, Role: LEADER
I20260812 06:18:38.066193  7638 ts_tablet_manager.cc:1434] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:38.066414  7626 heartbeater.cc:499] Master 127.7.68.126:41207 was elected leader, sending a full tablet report...
I20260812 06:18:38.066515  7640 consensus_queue.cc:237] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [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: "2ce5806569f84f7db0d8a7d509ecf91f" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 37599 } }
I20260812 06:18:38.069384  7475 catalog_manager.cc:5719] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f reported cstate change: term changed from 0 to 1, leader changed from <none> to 2ce5806569f84f7db0d8a7d509ecf91f (127.7.68.65). New cstate: current_term: 1 leader_uuid: "2ce5806569f84f7db0d8a7d509ecf91f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ce5806569f84f7db0d8a7d509ecf91f" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 37599 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:38.130934  7441 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.011s
I20260812 06:18:38.268319  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9): perf score=19.054940
I20260812 06:18:38.432718  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.164s	user 0.145s	sys 0.016s Metrics: {"bytes_written":12717734,"cfile_init":1,"compiler_manager_pool.queue_time_us":480,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":2516,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37054,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"thread_start_us":163,"threads_started":1,"update_count":1550}
I20260812 06:18:38.434226  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling LogGCOp(38049fdbd876468f8e77d0f7c00611c9): free 20743880 bytes of WAL
I20260812 06:18:38.434713  7556 log_reader.cc:385] T 38049fdbd876468f8e77d0f7c00611c9: removed 2 log segments from log reader
I20260812 06:18:38.434895  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000001 (ops 1-6)
I20260812 06:18:38.435057  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000002 (ops 7-11)
I20260812 06:18:38.440373  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: LogGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:38.440769  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:38.473404  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.032s	user 0.003s	sys 0.017s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5252,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.473948  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:38.489027  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.489603  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9): 16411393 bytes on disk
I20260812 06:18:38.490341  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.490855  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:38.666127  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.175s	user 0.132s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":817,"lbm_read_time_us":12685,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27739,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":322,"threads_started":5,"update_count":2500}
I20260812 06:18:38.666671  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:38.711321  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.044s	user 0.010s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.711862  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:38.725551  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.725966  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:38.856623  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.130s	user 0.098s	sys 0.032s 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":557,"lbm_read_time_us":9533,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24316,"lbm_writes_lt_1ms":443,"mutex_wait_us":272,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":40832,"update_count":2000}
I20260812 06:18:38.857236  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:38.908437  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.051s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18593,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.908875  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:38.918817  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.919333  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:39.044054  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.125s	user 0.099s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":469,"lbm_read_time_us":8947,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23444,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:39.044560  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:39.093566  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.049s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16881,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.094059  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.105357  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.105947  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:39.229581  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.123s	user 0.095s	sys 0.028s 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":818,"lbm_read_time_us":9524,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21771,"lbm_writes_lt_1ms":443,"mutex_wait_us":330,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:39.230361  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:39.269718  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.039s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14026,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.270251  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.283001  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.283569  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:39.437543  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.154s	user 0.106s	sys 0.047s 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":598,"lbm_read_time_us":13839,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22575,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:39.438032  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:39.481753  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.044s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15340,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.482244  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.493515  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.494158  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:39.609278  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.115s	user 0.099s	sys 0.015s 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":72,"lbm_read_time_us":7774,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20920,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:18:39.609932  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:39.647610  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.038s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16640,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.648234  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.658438  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.658988  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:39.691821  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1718,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2102,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:39.692628  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling LogGCOp(38049fdbd876468f8e77d0f7c00611c9): free 112239249 bytes of WAL
I20260812 06:18:39.692860  7556 log_reader.cc:385] T 38049fdbd876468f8e77d0f7c00611c9: removed 11 log segments from log reader
I20260812 06:18:39.692937  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000003 (ops 12-16)
I20260812 06:18:39.692992  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000004 (ops 17-21)
I20260812 06:18:39.693054  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000005 (ops 22-26)
I20260812 06:18:39.693094  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000006 (ops 27-30)
I20260812 06:18:39.693128  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000007 (ops 31-35)
I20260812 06:18:39.693166  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000008 (ops 36-40)
I20260812 06:18:39.693202  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000009 (ops 41-45)
I20260812 06:18:39.693238  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000010 (ops 46-50)
I20260812 06:18:39.693274  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000011 (ops 51-55)
I20260812 06:18:39.693310  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000012 (ops 56-60)
I20260812 06:18:39.693364  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000013 (ops 61-65)
I20260812 06:18:39.714737  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: LogGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:39.715173  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.731402  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.016s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.731889  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling LogGCOp(38049fdbd876468f8e77d0f7c00611c9): free 12017983 bytes of WAL
I20260812 06:18:39.732112  7556 log_reader.cc:385] T 38049fdbd876468f8e77d0f7c00611c9: removed 1 log segments from log reader
I20260812 06:18:39.732182  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000014 (ops 66-70)
I20260812 06:18:39.735049  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: LogGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:39.735337  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9): 462 bytes on disk
I20260812 06:18:39.735786  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.736227  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.751161  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.751720  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:39.916163  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.164s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":167,"lbm_read_time_us":10213,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33062,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:39.916635  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:39.976192  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.059s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21070,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.976738  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:39.990226  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.990767  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:40.138959  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.148s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":635,"lbm_read_time_us":8640,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29297,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:40.139647  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:40.181417  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.042s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.181896  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:40.319845  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.138s	user 0.114s	sys 0.024s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":134,"lbm_read_time_us":10877,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22819,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:40.321067  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:40.355731  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.034s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14528,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.356215  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:40.370651  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.371155  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:40.501423  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.130s	user 0.104s	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":760,"lbm_read_time_us":9396,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24973,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:40.502033  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:40.544080  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.042s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16779,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.544606  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:40.554848  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.555487  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:40.687839  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.132s	user 0.099s	sys 0.032s 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":171,"lbm_read_time_us":9149,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26174,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.688438  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:40.727648  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.039s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15592,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.728133  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:40.738657  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.739324  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:40.853801  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.114s	user 0.105s	sys 0.009s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":693,"lbm_read_time_us":7210,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23229,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:40.854589  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:40.908257  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.053s	user 0.017s	sys 0.035s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20814,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.908761  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:40.918751  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.919162  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:41.060734  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.141s	user 0.099s	sys 0.042s 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":316,"lbm_read_time_us":10584,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24310,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:18:41.061218  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:41.105399  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.044s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16243,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.105913  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:41.118562  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.119199  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:41.156630  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.037s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1352,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2386,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:41.157470  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling LogGCOp(38049fdbd876468f8e77d0f7c00611c9): free 117302573 bytes of WAL
I20260812 06:18:41.157758  7556 log_reader.cc:385] T 38049fdbd876468f8e77d0f7c00611c9: removed 12 log segments from log reader
I20260812 06:18:41.157824  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000015 (ops 71-75)
I20260812 06:18:41.157863  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000016 (ops 76-80)
I20260812 06:18:41.157895  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000017 (ops 81-84)
I20260812 06:18:41.157922  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000018 (ops 85-89)
I20260812 06:18:41.157948  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000019 (ops 90-94)
I20260812 06:18:41.157974  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000020 (ops 95-99)
I20260812 06:18:41.158008  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000021 (ops 100-104)
I20260812 06:18:41.158041  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000022 (ops 105-108)
I20260812 06:18:41.158068  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000023 (ops 109-113)
I20260812 06:18:41.158093  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000024 (ops 114-118)
I20260812 06:18:41.158121  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000025 (ops 119-123)
I20260812 06:18:41.158150  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000026 (ops 124-128)
I20260812 06:18:41.185570  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: LogGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.028s	user 0.001s	sys 0.025s Metrics: {}
I20260812 06:18:41.186079  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9): 483 bytes on disk
I20260812 06:18:41.186642  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.187252  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:41.208240  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.021s	user 0.008s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.208715  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:41.219466  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.219903  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:41.431667  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.212s	user 0.169s	sys 0.029s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1669,"lbm_read_time_us":13804,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34453,"lbm_writes_lt_1ms":643,"mutex_wait_us":755,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:41.432766  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:41.494383  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.061s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22844,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.494923  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:41.505591  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.506022  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:41.684508  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.178s	user 0.122s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":11950,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29635,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:18:41.685046  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:41.738699  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.053s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20658,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.739256  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:41.759123  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.020s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.759678  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:41.940829  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.181s	user 0.127s	sys 0.041s 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":216,"lbm_read_time_us":11513,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29810,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:41.941483  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:41.990790  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.049s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20199,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.991282  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:42.002524  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.003196  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:42.183858  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.180s	user 0.137s	sys 0.030s 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":677,"lbm_read_time_us":11744,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28562,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:18:42.184482  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:42.236752  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.052s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22255,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.237355  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:42.248517  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.248994  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:42.396456  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.147s	user 0.108s	sys 0.026s 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":387,"lbm_read_time_us":11567,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25851,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:42.397266  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=14.095187
I20260812 06:18:42.445648  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.048s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18062,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.446161  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:42.461474  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.462080  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:42.602319  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.140s	user 0.113s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"lbm_read_time_us":9498,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28862,"lbm_writes_lt_1ms":543,"mutex_wait_us":260,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:42.603034  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:42.639047  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.035s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15324,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.639823  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=2.188937
I20260812 06:18:42.656519  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.657058  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:42.686885  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushMRSOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.030s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1386,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1397,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:42.687638  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling LogGCOp(38049fdbd876468f8e77d0f7c00611c9): free 133024644 bytes of WAL
I20260812 06:18:42.687906  7556 log_reader.cc:385] T 38049fdbd876468f8e77d0f7c00611c9: removed 13 log segments from log reader
I20260812 06:18:42.687952  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000027 (ops 129-133)
I20260812 06:18:42.687983  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000028 (ops 134-138)
I20260812 06:18:42.688025  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000029 (ops 139-143)
I20260812 06:18:42.688071  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000030 (ops 144-148)
I20260812 06:18:42.688107  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000031 (ops 149-153)
I20260812 06:18:42.688182  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000032 (ops 154-158)
I20260812 06:18:42.688242  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000033 (ops 159-163)
I20260812 06:18:42.688316  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000034 (ops 164-168)
I20260812 06:18:42.688390  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000035 (ops 169-172)
I20260812 06:18:42.688454  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000036 (ops 173-177)
I20260812 06:18:42.688529  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000037 (ops 178-182)
I20260812 06:18:42.688596  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000038 (ops 183-187)
I20260812 06:18:42.688663  7556 log.cc:1079] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/38049fdbd876468f8e77d0f7c00611c9/wal-000000039 (ops 188-192)
I20260812 06:18:42.719192  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: LogGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:42.719734  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=5.165500
I20260812 06:18:42.738654  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.019s	user 0.004s	sys 0.012s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":7842,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:18:42.739144  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:42.745927  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":1748,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:18:42.746397  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9): perf score=1.000000
I20260812 06:18:42.861500  7441 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.730s	user 1.782s	sys 0.131s
I20260812 06:18:42.933892  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: MajorDeltaCompactionOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.187s	user 0.157s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":11352,"lbm_reads_lt_1ms":670,"lbm_write_time_us":35001,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:18:42.934458  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9): 481 bytes on disk
I20260812 06:18:42.934914  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: UndoDeltaBlockGCOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.935706  7627 maintenance_manager.cc:419] P 2ce5806569f84f7db0d8a7d509ecf91f: Scheduling FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9): perf score=10.126437
I20260812 06:18:42.952268  7441 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.005s	sys 0.000s
I20260812 06:18:42.952934  7441 tablet_server.cc:179] TabletServer@127.7.68.65:0 shutting down...
I20260812 06:18:42.973929  7556 maintenance_manager.cc:643] P 2ce5806569f84f7db0d8a7d509ecf91f: FlushDeltaMemStoresOp(38049fdbd876468f8e77d0f7c00611c9) complete. Timing: real 0.038s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16588,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.974561  7441 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:42.974978  7441 tablet_replica.cc:333] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f: stopping tablet replica
I20260812 06:18:42.975199  7441 raft_consensus.cc:2243] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.975500  7441 raft_consensus.cc:2272] T 38049fdbd876468f8e77d0f7c00611c9 P 2ce5806569f84f7db0d8a7d509ecf91f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.992290  7441 tablet_server.cc:196] TabletServer@127.7.68.65:0 shutdown complete.
I20260812 06:18:42.997013  7441 master.cc:562] Master@127.7.68.126:41207 shutting down...
I20260812 06:18:43.000609  7441 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.000785  7441 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.000885  7441 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2c95bfb8d85547d58a240939fbe1f13c: stopping tablet replica
I20260812 06:18:43.013098  7441 master.cc:584] Master@127.7.68.126:41207 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5268 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:43.098066  7441 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.68.126:35423
I20260812 06:18:43.098487  7441 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.100950  7664 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:43.100992  7441 server_base.cc:1061] running on GCE node
W20260812 06:18:43.101128  7661 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.101397  7662 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:43.101649  7441 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.101697  7441 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:43.101713  7441 hybrid_clock.cc:648] HybridClock initialized: now 1786515523101713 us; error 0 us; skew 500 ppm
I20260812 06:18:43.102581  7441 webserver.cc:533] Webserver started at http://127.7.68.126:41235/ using document root <none> and password file <none>
I20260812 06:18:43.102761  7441 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.102833  7441 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.102914  7441 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.103312  7441 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/master-0-root/instance:
uuid: "a0fb9947e8784389ad3039a1ebcacf15"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-5k54"
I20260812 06:18:43.105020  7441 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:43.105980  7669 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:43.106259  7441 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:43.106324  7441 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/master-0-root
uuid: "a0fb9947e8784389ad3039a1ebcacf15"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-5k54"
I20260812 06:18:43.106436  7441 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-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:43.113605  7441 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.113955  7441 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.118286  7441 rpc_server.cc:307] RPC server started. Bound to: 127.7.68.126:35423
I20260812 06:18:43.119797  7731 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:43.120289  7730 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.68.126:35423 every 8 connection(s)
I20260812 06:18:43.133090  7731 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15: Bootstrap starting.
I20260812 06:18:43.133935  7731 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.135006  7731 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15: No bootstrap required, opened a new log
I20260812 06:18:43.135413  7731 raft_consensus.cc:359] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0fb9947e8784389ad3039a1ebcacf15" member_type: VOTER }
I20260812 06:18:43.135605  7731 raft_consensus.cc:385] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.135653  7731 raft_consensus.cc:740] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a0fb9947e8784389ad3039a1ebcacf15, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.135816  7731 consensus_queue.cc:260] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [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: "a0fb9947e8784389ad3039a1ebcacf15" member_type: VOTER }
I20260812 06:18:43.135912  7731 raft_consensus.cc:399] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.135967  7731 raft_consensus.cc:493] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.136026  7731 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.136737  7731 raft_consensus.cc:515] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0fb9947e8784389ad3039a1ebcacf15" member_type: VOTER }
I20260812 06:18:43.136916  7731 leader_election.cc:304] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [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: a0fb9947e8784389ad3039a1ebcacf15; no voters: 
I20260812 06:18:43.137135  7731 leader_election.cc:290] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.137243  7734 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.137521  7734 raft_consensus.cc:697] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 1 LEADER]: Becoming Leader. State: Replica: a0fb9947e8784389ad3039a1ebcacf15, State: Running, Role: LEADER
I20260812 06:18:43.137640  7731 sys_catalog.cc:565] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.137660  7734 consensus_queue.cc:237] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [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: "a0fb9947e8784389ad3039a1ebcacf15" member_type: VOTER }
I20260812 06:18:43.138139  7736 sys_catalog.cc:455] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a0fb9947e8784389ad3039a1ebcacf15" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0fb9947e8784389ad3039a1ebcacf15" member_type: VOTER } }
I20260812 06:18:43.138170  7737 sys_catalog.cc:455] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a0fb9947e8784389ad3039a1ebcacf15. Latest consensus state: current_term: 1 leader_uuid: "a0fb9947e8784389ad3039a1ebcacf15" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0fb9947e8784389ad3039a1ebcacf15" member_type: VOTER } }
I20260812 06:18:43.138329  7737 sys_catalog.cc:458] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.138306  7736 sys_catalog.cc:458] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.138752  7743 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.139678  7743 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.139907  7441 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.141541  7743 catalog_manager.cc:1383] Generated new cluster ID: be0baaa760c541d292063f7174b35bf5
I20260812 06:18:43.141594  7743 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:43.149242  7743 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:43.149741  7743 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:43.155871  7743 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15: Generated new TSK 0
I20260812 06:18:43.156044  7743 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:43.172374  7441 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.174525  7757 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:43.174590  7441 server_base.cc:1061] running on GCE node
W20260812 06:18:43.174476  7753 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.174456  7754 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:43.174995  7441 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.175040  7441 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:43.175056  7441 hybrid_clock.cc:648] HybridClock initialized: now 1786515523175057 us; error 0 us; skew 500 ppm
I20260812 06:18:43.175980  7441 webserver.cc:533] Webserver started at http://127.7.68.65:36579/ using document root <none> and password file <none>
I20260812 06:18:43.176165  7441 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.176244  7441 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.176332  7441 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.176750  7441 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/instance:
uuid: "2a0890fa560a4068923da0cacfa06dcd"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-5k54"
I20260812 06:18:43.178251  7441 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:43.179216  7763 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:43.179519  7441 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:43.179585  7441 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root
uuid: "2a0890fa560a4068923da0cacfa06dcd"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-5k54"
I20260812 06:18:43.179641  7441 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-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:43.192780  7441 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.193092  7441 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.193351  7441 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:43.193835  7441 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:43.193874  7441 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.193907  7441 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:43.193969  7441 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.198207  7441 rpc_server.cc:307] RPC server started. Bound to: 127.7.68.65:38933
I20260812 06:18:43.198247  7831 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.68.65:38933 every 8 connection(s)
I20260812 06:18:43.207914  7832 heartbeater.cc:344] Connected to a master server at 127.7.68.126:35423
I20260812 06:18:43.208055  7832 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:43.208312  7832 heartbeater.cc:507] Master 127.7.68.126:35423 requested a full tablet report, sending...
I20260812 06:18:43.208945  7687 ts_manager.cc:194] Registered new tserver with Master: 2a0890fa560a4068923da0cacfa06dcd (127.7.68.65:38933)
I20260812 06:18:43.209606  7687 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38426
I20260812 06:18:43.209723  7441 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011083136s
I20260812 06:18:43.216814  7687 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38436:
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:43.225248  7792 tablet_service.cc:1511] Processing CreateTablet for tablet 354089d9effe4e3ba7e51133c395be9a (DEFAULT_TABLE table=heavy-update-compaction-test [id=84eb1536ab9c44e0af771cc11d3e2bcb]), partition=
I20260812 06:18:43.225543  7792 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 354089d9effe4e3ba7e51133c395be9a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.227581  7844 tablet_bootstrap.cc:492] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Bootstrap starting.
I20260812 06:18:43.228381  7844 tablet_bootstrap.cc:654] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.229334  7844 tablet_bootstrap.cc:492] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: No bootstrap required, opened a new log
I20260812 06:18:43.229408  7844 ts_tablet_manager.cc:1403] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:43.229744  7844 raft_consensus.cc:359] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a0890fa560a4068923da0cacfa06dcd" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 38933 } }
I20260812 06:18:43.229825  7844 raft_consensus.cc:385] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.229846  7844 raft_consensus.cc:740] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2a0890fa560a4068923da0cacfa06dcd, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.230016  7844 consensus_queue.cc:260] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [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: "2a0890fa560a4068923da0cacfa06dcd" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 38933 } }
I20260812 06:18:43.230108  7844 raft_consensus.cc:399] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.230132  7844 raft_consensus.cc:493] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.230167  7844 raft_consensus.cc:3060] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.230921  7844 raft_consensus.cc:515] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a0890fa560a4068923da0cacfa06dcd" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 38933 } }
I20260812 06:18:43.231103  7844 leader_election.cc:304] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [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: 2a0890fa560a4068923da0cacfa06dcd; no voters: 
I20260812 06:18:43.231341  7844 leader_election.cc:290] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.231491  7846 raft_consensus.cc:2804] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.231729  7846 raft_consensus.cc:697] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 1 LEADER]: Becoming Leader. State: Replica: 2a0890fa560a4068923da0cacfa06dcd, State: Running, Role: LEADER
I20260812 06:18:43.231751  7844 ts_tablet_manager.cc:1434] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:43.231801  7832 heartbeater.cc:499] Master 127.7.68.126:35423 was elected leader, sending a full tablet report...
I20260812 06:18:43.231884  7846 consensus_queue.cc:237] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [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: "2a0890fa560a4068923da0cacfa06dcd" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 38933 } }
I20260812 06:18:43.233204  7687 catalog_manager.cc:5719] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd reported cstate change: term changed from 0 to 1, leader changed from <none> to 2a0890fa560a4068923da0cacfa06dcd (127.7.68.65). New cstate: current_term: 1 leader_uuid: "2a0890fa560a4068923da0cacfa06dcd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a0890fa560a4068923da0cacfa06dcd" member_type: VOTER last_known_addr { host: "127.7.68.65" port: 38933 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:43.288549  7441 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.014s	sys 0.008s
I20260812 06:18:43.449159  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushMRSOp(354089d9effe4e3ba7e51133c395be9a): perf score=19.054940
I20260812 06:18:43.606635  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushMRSOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.157s	user 0.103s	sys 0.048s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":946,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41911,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:43.607466  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling LogGCOp(354089d9effe4e3ba7e51133c395be9a): free 20743880 bytes of WAL
I20260812 06:18:43.607712  7769 log_reader.cc:385] T 354089d9effe4e3ba7e51133c395be9a: removed 2 log segments from log reader
I20260812 06:18:43.607781  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000001 (ops 1-6)
I20260812 06:18:43.607839  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000002 (ops 7-11)
I20260812 06:18:43.612812  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: LogGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:43.613332  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:43.639468  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.639880  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:43.649755  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.650171  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:43.820254  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.170s	user 0.129s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":585,"lbm_read_time_us":11383,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30058,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":328,"threads_started":5,"update_count":2500}
I20260812 06:18:43.820812  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a): 20513813 bytes on disk
I20260812 06:18:43.823768  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a) 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:43.824303  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:43.870518  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.046s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20148,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.870923  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:43.883249  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4489,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.883728  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:44.027735  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.144s	user 0.098s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":10527,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26642,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:44.028471  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:44.082578  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.054s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20370,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.083117  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:44.097458  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.097916  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:44.244457  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.146s	user 0.119s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2508,"lbm_read_time_us":10434,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27803,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:44.245682  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=10.126437
I20260812 06:18:44.289335  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.043s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12553635,"delete_count":0,"lbm_write_time_us":17947,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":308,"mutex_wait_us":823,"reinsert_count":0,"update_count":1530}
I20260812 06:18:44.289880  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:44.313489  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:44.314007  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:44.328164  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.328631  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:44.507984  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.179s	user 0.106s	sys 0.071s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":501,"lbm_read_time_us":13054,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28354,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:18:44.508602  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:44.573770  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.065s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23060,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.574278  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:44.588640  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.589329  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:44.775964  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.186s	user 0.095s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":8920,"dirs.run_cpu_time_us":957,"dirs.run_wall_time_us":8867,"lbm_read_time_us":13078,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30729,"lbm_writes_lt_1ms":543,"mutex_wait_us":4325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:18:44.776521  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:44.840991  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.064s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23291,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.841548  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:44.851887  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.852485  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushMRSOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:44.892774  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushMRSOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.040s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1494,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1346,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:44.893463  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling LogGCOp(354089d9effe4e3ba7e51133c395be9a): free 124257242 bytes of WAL
I20260812 06:18:44.893749  7769 log_reader.cc:385] T 354089d9effe4e3ba7e51133c395be9a: removed 12 log segments from log reader
I20260812 06:18:44.893822  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000003 (ops 12-16)
I20260812 06:18:44.893872  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000004 (ops 17-20)
I20260812 06:18:44.893899  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000005 (ops 21-25)
I20260812 06:18:44.893940  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000006 (ops 26-30)
I20260812 06:18:44.893980  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000007 (ops 31-35)
I20260812 06:18:44.894016  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000008 (ops 36-40)
I20260812 06:18:44.894052  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000009 (ops 41-45)
I20260812 06:18:44.894088  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000010 (ops 46-50)
I20260812 06:18:44.894124  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000011 (ops 51-55)
I20260812 06:18:44.894160  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000012 (ops 56-60)
I20260812 06:18:44.894196  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000013 (ops 61-65)
I20260812 06:18:44.894232  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000014 (ops 66-70)
I20260812 06:18:44.920140  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: LogGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:44.920562  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a): 472 bytes on disk
I20260812 06:18:44.921195  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.921689  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=3.181125
I20260812 06:18:44.938799  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.017s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5994,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.939258  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:44.950791  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3461,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.951335  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:45.174106  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.223s	user 0.176s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":622,"lbm_read_time_us":15250,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38252,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":148,"threads_started":2,"update_count":3500}
I20260812 06:18:45.174686  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=18.063937
I20260812 06:18:45.234217  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.059s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27108,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.234714  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:45.248335  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.248899  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:45.408665  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.160s	user 0.142s	sys 0.016s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":10064,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33208,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:18:45.409487  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:45.455891  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.046s	user 0.043s	sys 0.003s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20482,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.456621  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:45.472678  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.473155  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:45.624231  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.151s	user 0.103s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":533,"lbm_read_time_us":8492,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27469,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.624751  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:45.676132  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.051s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22799,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.676697  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:45.844949  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.168s	user 0.099s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":384,"lbm_read_time_us":10358,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25850,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.845427  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:45.902823  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.057s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22452,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.903352  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:45.914201  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.914822  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:46.088141  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.173s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":10016,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27174,"lbm_writes_lt_1ms":543,"mutex_wait_us":263,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:18:46.088665  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:46.136204  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.047s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.136724  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.154399  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.154909  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushMRSOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:46.191623  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushMRSOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.036s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1412,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1465,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:46.192416  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a): 448 bytes on disk
I20260812 06:18:46.192817  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.193800  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=3.181125
I20260812 06:18:46.212919  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.019s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6480,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.213361  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling LogGCOp(354089d9effe4e3ba7e51133c395be9a): free 121006384 bytes of WAL
I20260812 06:18:46.213594  7769 log_reader.cc:385] T 354089d9effe4e3ba7e51133c395be9a: removed 12 log segments from log reader
I20260812 06:18:46.213639  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000015 (ops 71-75)
I20260812 06:18:46.213667  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000016 (ops 76-80)
I20260812 06:18:46.213726  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000017 (ops 81-85)
I20260812 06:18:46.213770  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000018 (ops 86-90)
I20260812 06:18:46.213811  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000019 (ops 91-95)
I20260812 06:18:46.213851  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000020 (ops 96-100)
I20260812 06:18:46.213897  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000021 (ops 101-105)
I20260812 06:18:46.213943  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000022 (ops 106-110)
I20260812 06:18:46.213972  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000023 (ops 111-114)
I20260812 06:18:46.214035  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000024 (ops 115-119)
I20260812 06:18:46.214074  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000025 (ops 120-124)
I20260812 06:18:46.214118  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000026 (ops 125-129)
I20260812 06:18:46.239042  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: LogGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:46.239566  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.260521  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.021s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.261078  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.270344  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3520,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.270846  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:46.511808  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.241s	user 0.148s	sys 0.092s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":898,"lbm_read_time_us":17670,"lbm_reads_lt_1ms":875,"lbm_write_time_us":42984,"lbm_writes_lt_1ms":843,"mutex_wait_us":1042,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":93440,"thread_start_us":78,"threads_started":1,"update_count":4000}
I20260812 06:18:46.514442  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=18.063937
I20260812 06:18:46.568367  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.053s	user 0.033s	sys 0.019s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":24068,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:46.569316  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.598801  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.029s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.599260  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.610347  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.611174  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:46.802804  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.191s	user 0.135s	sys 0.056s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020629,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1142,"lbm_read_time_us":14460,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39387,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3500}
I20260812 06:18:46.803540  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:46.850999  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.047s	user 0.030s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20248,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.851560  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.882339  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.031s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.882810  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:46.893201  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.893651  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:47.064582  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.171s	user 0.122s	sys 0.045s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":144,"lbm_read_time_us":10512,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36906,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":3000}
I20260812 06:18:47.065231  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:47.118747  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.053s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":25595,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.119243  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:47.130667  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.131247  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:47.290584  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.159s	user 0.123s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":931,"lbm_read_time_us":11758,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27396,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:18:47.291186  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:47.330932  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.040s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.331971  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:47.478219  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.146s	user 0.098s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":767,"lbm_read_time_us":9126,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23000,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2000}
I20260812 06:18:47.478754  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=14.095187
I20260812 06:18:47.538229  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.059s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18893,"lbm_writes_lt_1ms":403,"mutex_wait_us":38,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.538825  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:47.549183  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.549618  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushMRSOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:47.592053  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushMRSOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.042s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1442,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1473,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:47.592746  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling LogGCOp(354089d9effe4e3ba7e51133c395be9a): free 120553690 bytes of WAL
I20260812 06:18:47.592981  7769 log_reader.cc:385] T 354089d9effe4e3ba7e51133c395be9a: removed 12 log segments from log reader
I20260812 06:18:47.593026  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000027 (ops 130-134)
I20260812 06:18:47.593056  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000028 (ops 135-138)
I20260812 06:18:47.593119  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000029 (ops 139-143)
I20260812 06:18:47.593153  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000030 (ops 144-148)
I20260812 06:18:47.593195  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000031 (ops 149-153)
I20260812 06:18:47.593247  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000032 (ops 154-158)
I20260812 06:18:47.593286  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000033 (ops 159-163)
I20260812 06:18:47.593328  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000034 (ops 164-168)
I20260812 06:18:47.593366  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000035 (ops 169-172)
I20260812 06:18:47.593407  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000036 (ops 173-177)
I20260812 06:18:47.593444  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000037 (ops 178-182)
I20260812 06:18:47.593484  7769 log.cc:1079] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: Deleting log segment in path: /tmp/dist-test-task235piC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515517819063-7441-0/minicluster-data/ts-0-root/wals/354089d9effe4e3ba7e51133c395be9a/wal-000000038 (ops 183-187)
I20260812 06:18:47.619403  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: LogGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:47.619787  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a): 462 bytes on disk
I20260812 06:18:47.620339  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: UndoDeltaBlockGCOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.621100  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=3.181125
I20260812 06:18:47.634804  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:47.635250  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:47.645022  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3838,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.645488  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:47.877009  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.231s	user 0.161s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":370,"lbm_read_time_us":15802,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38885,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:18:47.877669  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=18.063937
I20260812 06:18:47.935153  7441 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.646s	user 1.784s	sys 0.132s
I20260812 06:18:47.937408  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.059s	user 0.041s	sys 0.016s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":28863,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.937860  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a): perf score=2.188937
I20260812 06:18:47.953236  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: FlushDeltaMemStoresOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:18:47.953778  7833 maintenance_manager.cc:419] P 2a0890fa560a4068923da0cacfa06dcd: Scheduling MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a): perf score=1.000000
I20260812 06:18:47.971611  7441 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.002s	sys 0.000s
I20260812 06:18:47.972119  7441 tablet_server.cc:179] TabletServer@127.7.68.65:0 shutting down...
I20260812 06:18:48.099655  7769 maintenance_manager.cc:643] P 2a0890fa560a4068923da0cacfa06dcd: MajorDeltaCompactionOp(354089d9effe4e3ba7e51133c395be9a) complete. Timing: real 0.146s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614711,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4739,"lbm_read_time_us":10218,"lbm_reads_lt_1ms":618,"lbm_write_time_us":26882,"lbm_writes_lt_1ms":643,"mutex_wait_us":79,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":78080,"update_count":3000}
I20260812 06:18:48.100427  7441 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.100697  7441 tablet_replica.cc:333] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd: stopping tablet replica
I20260812 06:18:48.100832  7441 raft_consensus.cc:2243] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.101014  7441 raft_consensus.cc:2272] T 354089d9effe4e3ba7e51133c395be9a P 2a0890fa560a4068923da0cacfa06dcd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.115409  7441 tablet_server.cc:196] TabletServer@127.7.68.65:0 shutdown complete.
I20260812 06:18:48.151211  7441 master.cc:562] Master@127.7.68.126:35423 shutting down...
I20260812 06:18:48.155207  7441 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.155392  7441 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.155524  7441 tablet_replica.cc:333] T 00000000000000000000000000000000 P a0fb9947e8784389ad3039a1ebcacf15: stopping tablet replica
I20260812 06:18:48.167835  7441 master.cc:584] Master@127.7.68.126:35423 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5153 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10423 ms total)

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