[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:06.132609  7385 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.54.126:39477
I20260812 06:19:06.133590  7385 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:06.134174  7385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:06.140774  7395 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:06.140823  7385 server_base.cc:1061] running on GCE node
W20260812 06:19:06.140767  7401 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:06.140981  7398 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:19:06.141502  7385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:06.141594  7385 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:06.141623  7385 hybrid_clock.cc:648] HybridClock initialized: now 1786515546141621 us; error 0 us; skew 500 ppm
I20260812 06:19:06.143302  7385 webserver.cc:533] Webserver started at http://127.7.54.126:39139/ using document root <none> and password file <none>
I20260812 06:19:06.143798  7385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:06.143852  7385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:06.144044  7385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:06.145653  7385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/master-0-root/instance:
uuid: "9d0776adfa2944f8b7dcddbcb398df73"
format_stamp: "Formatted at 2026-08-12 06:19:06 on dist-test-slave-4tdj"
I20260812 06:19:06.149056  7385 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:06.151131  7408 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:06.152086  7385 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:06.152186  7385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/master-0-root
uuid: "9d0776adfa2944f8b7dcddbcb398df73"
format_stamp: "Formatted at 2026-08-12 06:19:06 on dist-test-slave-4tdj"
I20260812 06:19:06.152295  7385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:06.180251  7385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:06.180918  7385 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:06.181078  7385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:06.188372  7501 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.54.126:39477 every 8 connection(s)
I20260812 06:19:06.188371  7385 rpc_server.cc:307] RPC server started. Bound to: 127.7.54.126:39477
I20260812 06:19:06.190590  7507 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:06.195715  7507 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73: Bootstrap starting.
I20260812 06:19:06.197896  7507 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:06.198766  7507 log.cc:826] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:06.200318  7507 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73: No bootstrap required, opened a new log
I20260812 06:19:06.202899  7507 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d0776adfa2944f8b7dcddbcb398df73" member_type: VOTER }
I20260812 06:19:06.203051  7507 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:06.203120  7507 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9d0776adfa2944f8b7dcddbcb398df73, State: Initialized, Role: FOLLOWER
I20260812 06:19:06.203653  7507 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [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: "9d0776adfa2944f8b7dcddbcb398df73" member_type: VOTER }
I20260812 06:19:06.203799  7507 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:06.203863  7507 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:06.203986  7507 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:06.204663  7507 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d0776adfa2944f8b7dcddbcb398df73" member_type: VOTER }
I20260812 06:19:06.205062  7507 leader_election.cc:304] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [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: 9d0776adfa2944f8b7dcddbcb398df73; no voters: 
I20260812 06:19:06.205339  7507 leader_election.cc:290] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:06.205433  7513 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:06.205636  7513 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 1 LEADER]: Becoming Leader. State: Replica: 9d0776adfa2944f8b7dcddbcb398df73, State: Running, Role: LEADER
I20260812 06:19:06.206046  7513 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [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: "9d0776adfa2944f8b7dcddbcb398df73" member_type: VOTER }
I20260812 06:19:06.206241  7507 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:06.207834  7516 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9d0776adfa2944f8b7dcddbcb398df73" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d0776adfa2944f8b7dcddbcb398df73" member_type: VOTER } }
I20260812 06:19:06.207846  7517 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9d0776adfa2944f8b7dcddbcb398df73. Latest consensus state: current_term: 1 leader_uuid: "9d0776adfa2944f8b7dcddbcb398df73" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d0776adfa2944f8b7dcddbcb398df73" member_type: VOTER } }
I20260812 06:19:06.207975  7516 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:06.207975  7517 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:06.208350  7533 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:06.208379  7385 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:06.210547  7533 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:06.214717  7533 catalog_manager.cc:1383] Generated new cluster ID: 5b6902f287c04633ac2bac6b70dfa809
I20260812 06:19:06.214782  7533 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:06.230650  7533 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:06.231487  7533 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:06.242568  7533 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73: Generated new TSK 0
I20260812 06:19:06.243175  7533 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:06.273231  7385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:06.276257  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
W20260812 06:19:06.276278  7540 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:06.276407  7544 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:06.276870  7385 server_base.cc:1061] running on GCE node
I20260812 06:19:06.277057  7385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:06.277102  7385 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:06.277129  7385 hybrid_clock.cc:648] HybridClock initialized: now 1786515546277129 us; error 0 us; skew 500 ppm
I20260812 06:19:06.278031  7385 webserver.cc:533] Webserver started at http://127.7.54.65:36533/ using document root <none> and password file <none>
I20260812 06:19:06.278203  7385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:06.278257  7385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:06.278354  7385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:06.278801  7385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/instance:
uuid: "7a6aff6f34ee4e10a8a4c432c4cfabb4"
format_stamp: "Formatted at 2026-08-12 06:19:06 on dist-test-slave-4tdj"
I20260812 06:19:06.280588  7385 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:06.281622  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:19:06.281870  7385 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:06.281941  7385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root
uuid: "7a6aff6f34ee4e10a8a4c432c4cfabb4"
format_stamp: "Formatted at 2026-08-12 06:19:06 on dist-test-slave-4tdj"
I20260812 06:19:06.282013  7385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:06.288378  7385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:06.288769  7385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:06.289193  7385 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:06.290025  7385 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:06.290076  7385 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:06.290120  7385 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:06.290151  7385 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:06.296197  7385 rpc_server.cc:307] RPC server started. Bound to: 127.7.54.65:38599
I20260812 06:19:06.296257  7654 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.54.65:38599 every 8 connection(s)
I20260812 06:19:06.305734  7657 heartbeater.cc:344] Connected to a master server at 127.7.54.126:39477
I20260812 06:19:06.305971  7657 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:06.306456  7657 heartbeater.cc:507] Master 127.7.54.126:39477 requested a full tablet report, sending...
I20260812 06:19:06.307861  7449 ts_manager.cc:194] Registered new tserver with Master: 7a6aff6f34ee4e10a8a4c432c4cfabb4 (127.7.54.65:38599)
I20260812 06:19:06.307982  7385 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011182755s
I20260812 06:19:06.309366  7449 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54764
I20260812 06:19:06.316577  7449 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54766:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:06.330016  7597 tablet_service.cc:1511] Processing CreateTablet for tablet 3caaa305fa2c420186e78c981ea9b991 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3c18421c069c4beca2592ff92cd3f217]), partition=
I20260812 06:19:06.330535  7597 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3caaa305fa2c420186e78c981ea9b991. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:06.332790  7677 tablet_bootstrap.cc:492] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Bootstrap starting.
I20260812 06:19:06.334270  7677 tablet_bootstrap.cc:654] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:06.335427  7677 tablet_bootstrap.cc:492] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: No bootstrap required, opened a new log
I20260812 06:19:06.335528  7677 ts_tablet_manager.cc:1403] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:06.335963  7677 raft_consensus.cc:359] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a6aff6f34ee4e10a8a4c432c4cfabb4" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 38599 } }
I20260812 06:19:06.336072  7677 raft_consensus.cc:385] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:06.336105  7677 raft_consensus.cc:740] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7a6aff6f34ee4e10a8a4c432c4cfabb4, State: Initialized, Role: FOLLOWER
I20260812 06:19:06.336248  7677 consensus_queue.cc:260] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [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: "7a6aff6f34ee4e10a8a4c432c4cfabb4" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 38599 } }
I20260812 06:19:06.336351  7677 raft_consensus.cc:399] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:06.336398  7677 raft_consensus.cc:493] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:06.336448  7677 raft_consensus.cc:3060] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:06.337198  7677 raft_consensus.cc:515] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a6aff6f34ee4e10a8a4c432c4cfabb4" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 38599 } }
I20260812 06:19:06.337337  7677 leader_election.cc:304] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [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: 7a6aff6f34ee4e10a8a4c432c4cfabb4; no voters: 
I20260812 06:19:06.337560  7677 leader_election.cc:290] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:06.337877  7682 raft_consensus.cc:2804] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:06.337896  7677 ts_tablet_manager.cc:1434] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:06.338349  7657 heartbeater.cc:499] Master 127.7.54.126:39477 was elected leader, sending a full tablet report...
I20260812 06:19:06.338434  7682 raft_consensus.cc:697] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 1 LEADER]: Becoming Leader. State: Replica: 7a6aff6f34ee4e10a8a4c432c4cfabb4, State: Running, Role: LEADER
I20260812 06:19:06.338577  7682 consensus_queue.cc:237] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [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: "7a6aff6f34ee4e10a8a4c432c4cfabb4" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 38599 } }
I20260812 06:19:06.341298  7449 catalog_manager.cc:5719] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7a6aff6f34ee4e10a8a4c432c4cfabb4 (127.7.54.65). New cstate: current_term: 1 leader_uuid: "7a6aff6f34ee4e10a8a4c432c4cfabb4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a6aff6f34ee4e10a8a4c432c4cfabb4" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 38599 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:06.403858  7385 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.018s	sys 0.007s
I20260812 06:19:06.547350  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushMRSOp(3caaa305fa2c420186e78c981ea9b991): perf score=19.054940
I20260812 06:19:06.738206  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushMRSOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.191s	user 0.143s	sys 0.044s Metrics: {"bytes_written":16040686,"cfile_init":1,"compiler_manager_pool.queue_time_us":193,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":898,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47220,"lbm_writes_lt_1ms":858,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":337792,"thread_start_us":116,"threads_started":1,"update_count":1955}
I20260812 06:19:06.739478  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling LogGCOp(3caaa305fa2c420186e78c981ea9b991): free 20743880 bytes of WAL
I20260812 06:19:06.739805  7557 log_reader.cc:385] T 3caaa305fa2c420186e78c981ea9b991: removed 2 log segments from log reader
I20260812 06:19:06.739877  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000001 (ops 1-6)
I20260812 06:19:06.739934  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000002 (ops 7-11)
I20260812 06:19:06.745151  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: LogGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:06.745515  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=5.165500
I20260812 06:19:06.766325  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.021s	user 0.018s	sys 0.000s Metrics: {"bytes_written":6523090,"delete_count":0,"lbm_write_time_us":8554,"lbm_writes_lt_1ms":162,"reinsert_count":0,"update_count":795}
I20260812 06:19:06.766798  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991): 16821647 bytes on disk
I20260812 06:19:06.767371  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991) 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:19:06.767784  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:06.774693  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1641152,"delete_count":0,"lbm_write_time_us":2111,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 06:19:06.775113  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:07.365931  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.591s	user 0.400s	sys 0.188s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28507918,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2425,"lbm_read_time_us":47947,"lbm_reads_1-10_ms":4,"lbm_reads_lt_1ms":647,"lbm_write_time_us":110973,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":630,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":1253,"threads_started":6,"update_count":2950}
I20260812 06:19:07.367893  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:07.545332  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.177s	user 0.085s	sys 0.082s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":77660,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.547044  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:07.604591  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.057s	user 0.012s	sys 0.030s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":18587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.605633  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:08.175298  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.569s	user 0.393s	sys 0.170s 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":1792,"lbm_read_time_us":34294,"lbm_reads_lt_1ms":564,"lbm_write_time_us":118338,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":540,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":722,"threads_started":6,"update_count":2500}
I20260812 06:19:08.176795  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:08.324394  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.147s	user 0.085s	sys 0.059s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":54137,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.326436  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:08.388442  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.061s	user 0.027s	sys 0.032s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":22730,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.390951  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:08.770397  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.379s	user 0.281s	sys 0.093s 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":673,"lbm_read_time_us":27444,"lbm_reads_1-10_ms":2,"lbm_reads_lt_1ms":570,"lbm_write_time_us":67414,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":361,"threads_started":6,"update_count":2500}
I20260812 06:19:08.771401  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=11.118625
I20260812 06:19:08.923825  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.152s	user 0.076s	sys 0.046s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":55543,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.924391  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=6.157687
I20260812 06:19:09.018848  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.094s	user 0.052s	sys 0.020s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":32111,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:09.020277  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:09.474068  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.453s	user 0.335s	sys 0.116s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2657,"lbm_read_time_us":30659,"lbm_reads_lt_1ms":564,"lbm_write_time_us":87490,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":1297,"threads_started":6,"update_count":2500}
I20260812 06:19:09.476080  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:09.625532  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.149s	user 0.103s	sys 0.043s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":66977,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:09.626482  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:09.681191  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.054s	user 0.026s	sys 0.023s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":10070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.683794  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:10.165733  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.481s	user 0.337s	sys 0.136s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2712,"lbm_read_time_us":35077,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":563,"lbm_write_time_us":79382,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":541,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":1434,"threads_started":6,"update_count":2500}
I20260812 06:19:10.167119  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:10.330901  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.163s	user 0.107s	sys 0.050s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":70061,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.332589  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:10.368976  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.036s	user 0.029s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":13507,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.370805  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushMRSOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:10.462442  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushMRSOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.091s	user 0.074s	sys 0.009s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":135,"dirs.run_cpu_time_us":733,"dirs.run_wall_time_us":2384,"drs_written":1,"lbm_read_time_us":167,"lbm_reads_lt_1ms":4,"lbm_write_time_us":5645,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:10.463973  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling LogGCOp(3caaa305fa2c420186e78c981ea9b991): free 121006438 bytes of WAL
I20260812 06:19:10.464982  7557 log_reader.cc:385] T 3caaa305fa2c420186e78c981ea9b991: removed 12 log segments from log reader
I20260812 06:19:10.465291  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000003 (ops 12-16)
I20260812 06:19:10.465417  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000004 (ops 17-21)
I20260812 06:19:10.465476  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000005 (ops 22-26)
I20260812 06:19:10.465627  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000006 (ops 27-31)
I20260812 06:19:10.465720  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000007 (ops 32-36)
I20260812 06:19:10.465927  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000008 (ops 37-41)
I20260812 06:19:10.466118  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000009 (ops 42-46)
I20260812 06:19:10.466431  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000010 (ops 47-50)
I20260812 06:19:10.466656  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000011 (ops 51-55)
I20260812 06:19:10.466888  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000012 (ops 56-60)
I20260812 06:19:10.467101  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000013 (ops 61-65)
I20260812 06:19:10.467257  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000014 (ops 66-70)
I20260812 06:19:10.546792  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: LogGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.082s	user 0.000s	sys 0.082s Metrics: {}
I20260812 06:19:10.560350  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991): 475 bytes on disk
I20260812 06:19:10.560922  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.563979  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:10.628144  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.063s	user 0.028s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":15103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.629149  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling LogGCOp(3caaa305fa2c420186e78c981ea9b991): free 11564875 bytes of WAL
I20260812 06:19:10.629570  7557 log_reader.cc:385] T 3caaa305fa2c420186e78c981ea9b991: removed 1 log segments from log reader
I20260812 06:19:10.629681  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000015 (ops 71-74)
I20260812 06:19:10.635337  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: LogGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:10.636792  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:10.717662  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.080s	user 0.058s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":33313,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.718381  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:11.509550  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.791s	user 0.530s	sys 0.249s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3708,"lbm_read_time_us":64078,"lbm_reads_1-10_ms":2,"lbm_reads_lt_1ms":772,"lbm_write_time_us":140101,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":740,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":1636,"threads_started":7,"update_count":3500}
I20260812 06:19:11.512785  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=15.087375
I20260812 06:19:11.636685  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.123s	user 0.057s	sys 0.063s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":57185,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:11.637141  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:11.658339  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.658780  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:11.667973  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3319,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.668416  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:11.861246  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.193s	user 0.097s	sys 0.092s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":788,"lbm_read_time_us":14131,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33473,"lbm_writes_lt_1ms":643,"mutex_wait_us":251,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:11.861891  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:11.916376  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.054s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25235,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.916923  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:11.931665  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.932264  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:12.096932  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.164s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":13940,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26898,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:12.097450  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:12.153417  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.056s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18212,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:12.154006  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:12.169076  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.169564  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:12.336644  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.167s	user 0.131s	sys 0.032s 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":172,"lbm_read_time_us":12059,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28970,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:12.337185  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=11.118625
I20260812 06:19:12.374395  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.037s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15661,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:12.374931  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:12.387210  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.387615  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:12.531797  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.144s	user 0.103s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":733,"lbm_read_time_us":9570,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24589,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:12.532531  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=11.118625
I20260812 06:19:12.562053  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.029s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12553635,"delete_count":0,"lbm_write_time_us":12767,"lbm_writes_lt_1ms":309,"reinsert_count":0,"update_count":1530}
I20260812 06:19:12.562660  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:12.573734  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:12.574333  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:12.700438  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.126s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1012,"lbm_read_time_us":8469,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25289,"lbm_writes_lt_1ms":443,"mutex_wait_us":336,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:12.701061  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=10.126437
I20260812 06:19:12.739967  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307576,"delete_count":0,"lbm_write_time_us":16638,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:12.740459  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:12.750331  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.750953  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushMRSOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:12.783463  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushMRSOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.032s	user 0.025s	sys 0.006s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1420,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:12.784291  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling LogGCOp(3caaa305fa2c420186e78c981ea9b991): free 121006461 bytes of WAL
I20260812 06:19:12.784526  7557 log_reader.cc:385] T 3caaa305fa2c420186e78c981ea9b991: removed 12 log segments from log reader
I20260812 06:19:12.784581  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000016 (ops 75-79)
I20260812 06:19:12.784621  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000017 (ops 80-84)
I20260812 06:19:12.784657  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000018 (ops 85-89)
I20260812 06:19:12.784682  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000019 (ops 90-94)
I20260812 06:19:12.784713  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000020 (ops 95-99)
I20260812 06:19:12.784745  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000021 (ops 100-104)
I20260812 06:19:12.784776  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000022 (ops 105-108)
I20260812 06:19:12.784807  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000023 (ops 109-113)
I20260812 06:19:12.784838  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000024 (ops 114-118)
I20260812 06:19:12.784870  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000025 (ops 119-123)
I20260812 06:19:12.784900  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000026 (ops 124-128)
I20260812 06:19:12.784931  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000027 (ops 129-133)
I20260812 06:19:12.807957  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: LogGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.023s	user 0.003s	sys 0.019s Metrics: {}
I20260812 06:19:12.808387  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991): 472 bytes on disk
I20260812 06:19:12.808862  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:12.809368  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=3.181125
I20260812 06:19:12.821692  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4635977,"delete_count":0,"lbm_write_time_us":4544,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:19:12.822134  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:12.831156  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":3158,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:19:12.831593  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:12.998354  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.167s	user 0.105s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918409,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":156,"lbm_read_time_us":13518,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32612,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:19:12.998880  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:13.042943  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.044s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17535,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.043520  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:13.053676  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.054371  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:13.207175  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.153s	user 0.122s	sys 0.029s 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":1092,"lbm_read_time_us":11505,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26711,"lbm_writes_lt_1ms":543,"mutex_wait_us":334,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:13.207787  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=12.110812
I20260812 06:19:13.251819  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":13784349,"delete_count":0,"lbm_write_time_us":18347,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:19:13.252331  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.196750
I20260812 06:19:13.273345  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.021s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3036009,"delete_count":0,"lbm_write_time_us":3382,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:19:13.273883  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:13.283528  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3554,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.284052  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:13.457891  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.174s	user 0.095s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":914,"lbm_read_time_us":14616,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27764,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:13.458482  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:13.522728  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.064s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29003,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.523253  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:13.533463  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.533926  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:13.706694  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.173s	user 0.105s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":620,"lbm_read_time_us":12483,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29366,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:13.707260  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=14.095187
I20260812 06:19:13.765082  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.058s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.765729  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:13.776373  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.776832  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:13.930563  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.154s	user 0.109s	sys 0.044s 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":643,"lbm_read_time_us":12152,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26508,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:13.931154  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=11.118625
I20260812 06:19:13.962141  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.031s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13300,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:13.962672  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:13.977598  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5365,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.978190  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:14.114136  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.136s	user 0.105s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":9228,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21812,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:14.114890  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=10.126437
I20260812 06:19:14.152823  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.038s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16994,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.153362  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=2.188937
I20260812 06:19:14.169252  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.169819  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushMRSOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:14.197670  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushMRSOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1230,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1688,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:14.198432  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling LogGCOp(3caaa305fa2c420186e78c981ea9b991): free 120553651 bytes of WAL
I20260812 06:19:14.198652  7557 log_reader.cc:385] T 3caaa305fa2c420186e78c981ea9b991: removed 12 log segments from log reader
I20260812 06:19:14.198712  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000028 (ops 134-138)
I20260812 06:19:14.198750  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000029 (ops 139-143)
I20260812 06:19:14.198782  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000030 (ops 144-148)
I20260812 06:19:14.198803  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000031 (ops 149-152)
I20260812 06:19:14.198833  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000032 (ops 153-157)
I20260812 06:19:14.198866  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000033 (ops 158-162)
I20260812 06:19:14.198894  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000034 (ops 163-167)
I20260812 06:19:14.198923  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000035 (ops 168-172)
I20260812 06:19:14.198951  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000036 (ops 173-176)
I20260812 06:19:14.198980  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000037 (ops 177-181)
I20260812 06:19:14.199013  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000038 (ops 182-186)
I20260812 06:19:14.199043  7557 log.cc:1079] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/3caaa305fa2c420186e78c981ea9b991/wal-000000039 (ops 187-191)
I20260812 06:19:14.225355  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: LogGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:14.225924  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991): 472 bytes on disk
I20260812 06:19:14.226500  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: UndoDeltaBlockGCOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.227196  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=3.181125
I20260812 06:19:14.241475  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.014s	user 0.000s	sys 0.012s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":5596,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:19:14.241988  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.196750
I20260812 06:19:14.255175  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4807,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:19:14.255966  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:14.377682  7385 heavy-update-compaction-itest.cc:229] Time spent updating: real 7.974s	user 2.751s	sys 0.244s
I20260812 06:19:14.411408  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.155s	user 0.130s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918307,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":10803,"lbm_reads_lt_1ms":670,"lbm_write_time_us":32208,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:19:14.411890  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991): perf score=10.126437
I20260812 06:19:14.441692  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: FlushDeltaMemStoresOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.030s	user 0.026s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12284,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.442173  7658 maintenance_manager.cc:419] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: Scheduling MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991): perf score=1.000000
I20260812 06:19:14.450911  7385 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.004s	sys 0.004s
I20260812 06:19:14.451818  7385 tablet_server.cc:179] TabletServer@127.7.54.65:0 shutting down...
I20260812 06:19:14.549124  7557 maintenance_manager.cc:643] P 7a6aff6f34ee4e10a8a4c432c4cfabb4: MajorDeltaCompactionOp(3caaa305fa2c420186e78c981ea9b991) complete. Timing: real 0.107s	user 0.073s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610743,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":212,"lbm_read_time_us":7987,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20024,"lbm_writes_lt_1ms":343,"mutex_wait_us":51,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":1500}
I20260812 06:19:14.550684  7385 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:14.551110  7385 tablet_replica.cc:333] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4: stopping tablet replica
I20260812 06:19:14.551359  7385 raft_consensus.cc:2243] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:14.551604  7385 raft_consensus.cc:2272] T 3caaa305fa2c420186e78c981ea9b991 P 7a6aff6f34ee4e10a8a4c432c4cfabb4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:14.567190  7385 tablet_server.cc:196] TabletServer@127.7.54.65:0 shutdown complete.
I20260812 06:19:14.580564  7385 master.cc:562] Master@127.7.54.126:39477 shutting down...
I20260812 06:19:14.583758  7385 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:14.583906  7385 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:14.583958  7385 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9d0776adfa2944f8b7dcddbcb398df73: stopping tablet replica
I20260812 06:19:14.595875  7385 master.cc:584] Master@127.7.54.126:39477 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (8539 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:14.672132  7385 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.54.126:42841
I20260812 06:19:14.672480  7385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:14.674409  7780 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:14.674451  7777 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:14.674547  7385 server_base.cc:1061] running on GCE node
W20260812 06:19:14.674659  7784 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:14.674909  7385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:14.674947  7385 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:14.674961  7385 hybrid_clock.cc:648] HybridClock initialized: now 1786515554674962 us; error 0 us; skew 500 ppm
I20260812 06:19:14.675679  7385 webserver.cc:533] Webserver started at http://127.7.54.126:38957/ using document root <none> and password file <none>
I20260812 06:19:14.675832  7385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:14.675866  7385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:14.675921  7385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:14.676234  7385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/master-0-root/instance:
uuid: "01bad2f77d8b40988dab6354a0525a2c"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-4tdj"
I20260812 06:19:14.677553  7385 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:14.678402  7792 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.678614  7385 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:14.678679  7385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/master-0-root
uuid: "01bad2f77d8b40988dab6354a0525a2c"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-4tdj"
I20260812 06:19:14.678762  7385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:14.736984  7385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:14.737428  7385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:14.741556  7385 rpc_server.cc:307] RPC server started. Bound to: 127.7.54.126:42841
I20260812 06:19:14.749723  7898 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:14.749770  7897 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.54.126:42841 every 8 connection(s)
I20260812 06:19:14.751642  7898 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c: Bootstrap starting.
I20260812 06:19:14.752389  7898 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:14.753348  7898 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c: No bootstrap required, opened a new log
I20260812 06:19:14.753718  7898 raft_consensus.cc:359] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "01bad2f77d8b40988dab6354a0525a2c" member_type: VOTER }
I20260812 06:19:14.753803  7898 raft_consensus.cc:385] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:14.753830  7898 raft_consensus.cc:740] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 01bad2f77d8b40988dab6354a0525a2c, State: Initialized, Role: FOLLOWER
I20260812 06:19:14.753943  7898 consensus_queue.cc:260] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [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: "01bad2f77d8b40988dab6354a0525a2c" member_type: VOTER }
I20260812 06:19:14.754030  7898 raft_consensus.cc:399] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:14.754060  7898 raft_consensus.cc:493] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:14.754096  7898 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:14.754776  7898 raft_consensus.cc:515] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "01bad2f77d8b40988dab6354a0525a2c" member_type: VOTER }
I20260812 06:19:14.754894  7898 leader_election.cc:304] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [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: 01bad2f77d8b40988dab6354a0525a2c; no voters: 
I20260812 06:19:14.755034  7898 leader_election.cc:290] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:14.755142  7904 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:14.755331  7904 raft_consensus.cc:697] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 1 LEADER]: Becoming Leader. State: Replica: 01bad2f77d8b40988dab6354a0525a2c, State: Running, Role: LEADER
I20260812 06:19:14.755509  7898 sys_catalog.cc:565] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:14.755494  7904 consensus_queue.cc:237] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [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: "01bad2f77d8b40988dab6354a0525a2c" member_type: VOTER }
I20260812 06:19:14.755919  7907 sys_catalog.cc:455] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 01bad2f77d8b40988dab6354a0525a2c. Latest consensus state: current_term: 1 leader_uuid: "01bad2f77d8b40988dab6354a0525a2c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "01bad2f77d8b40988dab6354a0525a2c" member_type: VOTER } }
I20260812 06:19:14.755906  7905 sys_catalog.cc:455] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "01bad2f77d8b40988dab6354a0525a2c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "01bad2f77d8b40988dab6354a0525a2c" member_type: VOTER } }
I20260812 06:19:14.756042  7907 sys_catalog.cc:458] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:14.756099  7905 sys_catalog.cc:458] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:14.756660  7915 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:14.757349  7915 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:14.757543  7385 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:14.759081  7915 catalog_manager.cc:1383] Generated new cluster ID: 4798380e6a9444c9a80807150b365c9e
I20260812 06:19:14.759130  7915 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:14.769615  7915 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:14.770107  7915 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:14.777024  7915 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c: Generated new TSK 0
I20260812 06:19:14.777160  7915 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:14.789695  7385 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:14.791543  7943 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:19:14.791615  7385 server_base.cc:1061] running on GCE node
W20260812 06:19:14.791709  7945 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:14.791709  7940 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:14.792007  7385 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:14.792054  7385 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:14.792076  7385 hybrid_clock.cc:648] HybridClock initialized: now 1786515554792075 us; error 0 us; skew 500 ppm
I20260812 06:19:14.792860  7385 webserver.cc:533] Webserver started at http://127.7.54.65:44201/ using document root <none> and password file <none>
I20260812 06:19:14.793017  7385 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:14.793068  7385 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:14.793143  7385 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:14.793526  7385 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/instance:
uuid: "9171940a3fd44ecbb049da3afb04afb6"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-4tdj"
I20260812 06:19:14.795307  7385 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:14.796180  7952 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.796381  7385 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:14.796450  7385 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root
uuid: "9171940a3fd44ecbb049da3afb04afb6"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-4tdj"
I20260812 06:19:14.796519  7385 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:14.810081  7385 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:14.810489  7385 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:14.810788  7385 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:14.811241  7385 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:14.811280  7385 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.811323  7385 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:14.811352  7385 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.815364  7385 rpc_server.cc:307] RPC server started. Bound to: 127.7.54.65:42003
I20260812 06:19:14.816573  8094 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.54.65:42003 every 8 connection(s)
I20260812 06:19:14.820827  8095 heartbeater.cc:344] Connected to a master server at 127.7.54.126:42841
I20260812 06:19:14.820917  8095 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:14.821096  8095 heartbeater.cc:507] Master 127.7.54.126:42841 requested a full tablet report, sending...
I20260812 06:19:14.821689  7819 ts_manager.cc:194] Registered new tserver with Master: 9171940a3fd44ecbb049da3afb04afb6 (127.7.54.65:42003)
I20260812 06:19:14.822394  7819 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34606
I20260812 06:19:14.822702  7385 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006597979s
I20260812 06:19:14.828855  7819 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34614:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:14.836944  8020 tablet_service.cc:1511] Processing CreateTablet for tablet 50ad6b44debf4caf969132985b698f7e (DEFAULT_TABLE table=heavy-update-compaction-test [id=3b9a17d7c0054428a112261849627363]), partition=
I20260812 06:19:14.837154  8020 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 50ad6b44debf4caf969132985b698f7e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:14.838934  8115 tablet_bootstrap.cc:492] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Bootstrap starting.
I20260812 06:19:14.839874  8115 tablet_bootstrap.cc:654] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:14.840801  8115 tablet_bootstrap.cc:492] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: No bootstrap required, opened a new log
I20260812 06:19:14.840871  8115 ts_tablet_manager.cc:1403] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:14.841238  8115 raft_consensus.cc:359] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9171940a3fd44ecbb049da3afb04afb6" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 42003 } }
I20260812 06:19:14.841318  8115 raft_consensus.cc:385] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:14.841351  8115 raft_consensus.cc:740] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9171940a3fd44ecbb049da3afb04afb6, State: Initialized, Role: FOLLOWER
I20260812 06:19:14.841476  8115 consensus_queue.cc:260] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [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: "9171940a3fd44ecbb049da3afb04afb6" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 42003 } }
I20260812 06:19:14.841548  8115 raft_consensus.cc:399] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:14.841584  8115 raft_consensus.cc:493] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:14.841634  8115 raft_consensus.cc:3060] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:14.842343  8115 raft_consensus.cc:515] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9171940a3fd44ecbb049da3afb04afb6" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 42003 } }
I20260812 06:19:14.842486  8115 leader_election.cc:304] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [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: 9171940a3fd44ecbb049da3afb04afb6; no voters: 
I20260812 06:19:14.842664  8115 leader_election.cc:290] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:14.842774  8117 raft_consensus.cc:2804] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:14.842945  8095 heartbeater.cc:499] Master 127.7.54.126:42841 was elected leader, sending a full tablet report...
I20260812 06:19:14.842970  8117 raft_consensus.cc:697] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 1 LEADER]: Becoming Leader. State: Replica: 9171940a3fd44ecbb049da3afb04afb6, State: Running, Role: LEADER
I20260812 06:19:14.842932  8115 ts_tablet_manager.cc:1434] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:14.843096  8117 consensus_queue.cc:237] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [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: "9171940a3fd44ecbb049da3afb04afb6" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 42003 } }
I20260812 06:19:14.844300  7819 catalog_manager.cc:5719] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9171940a3fd44ecbb049da3afb04afb6 (127.7.54.65). New cstate: current_term: 1 leader_uuid: "9171940a3fd44ecbb049da3afb04afb6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9171940a3fd44ecbb049da3afb04afb6" member_type: VOTER last_known_addr { host: "127.7.54.65" port: 42003 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:14.898317  7385 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.016s	sys 0.006s
I20260812 06:19:15.067054  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushMRSOp(50ad6b44debf4caf969132985b698f7e): perf score=23.023690
I20260812 06:19:15.211647  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushMRSOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.144s	user 0.089s	sys 0.052s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":168,"dirs.run_wall_time_us":830,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38285,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:15.212414  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling LogGCOp(50ad6b44debf4caf969132985b698f7e): free 20743880 bytes of WAL
I20260812 06:19:15.212658  7969 log_reader.cc:385] T 50ad6b44debf4caf969132985b698f7e: removed 2 log segments from log reader
I20260812 06:19:15.212719  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000001 (ops 1-6)
I20260812 06:19:15.212750  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000002 (ops 7-11)
I20260812 06:19:15.216316  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: LogGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.004s	user 0.002s	sys 0.000s Metrics: {}
I20260812 06:19:15.216650  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:15.233072  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5153,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.233477  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e): 20513814 bytes on disk
I20260812 06:19:15.233845  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.234238  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:15.386813  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.152s	user 0.103s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":463,"lbm_read_time_us":9601,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25571,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":288,"threads_started":5,"update_count":2000}
I20260812 06:19:15.387455  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:15.436851  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.049s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.437522  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:15.574257  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.137s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":226,"lbm_read_time_us":10137,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20997,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:19:15.574904  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:15.628234  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.053s	user 0.040s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24970,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.628741  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:15.640388  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.640811  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:15.824402  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.183s	user 0.137s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":87,"lbm_read_time_us":13202,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27310,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2500}
I20260812 06:19:15.825047  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:15.868916  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.044s	user 0.035s	sys 0.003s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17933,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.869426  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:15.879899  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.880501  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:16.028997  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.148s	user 0.110s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":9212,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27785,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:16.029613  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=11.118625
I20260812 06:19:16.063823  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.034s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:16.064404  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:16.089289  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5316,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.089772  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:16.100178  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.100562  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:16.251029  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.150s	user 0.111s	sys 0.029s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":232,"lbm_read_time_us":9669,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27750,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:16.251585  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:16.297132  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.045s	user 0.023s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16746,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.297585  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:16.308530  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.309206  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushMRSOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:16.339064  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushMRSOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.030s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1243,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1927,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:16.339716  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling LogGCOp(50ad6b44debf4caf969132985b698f7e): free 115943169 bytes of WAL
I20260812 06:19:16.339933  7969 log_reader.cc:385] T 50ad6b44debf4caf969132985b698f7e: removed 11 log segments from log reader
I20260812 06:19:16.339990  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000003 (ops 12-16)
I20260812 06:19:16.340027  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000004 (ops 17-21)
I20260812 06:19:16.340060  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000005 (ops 22-26)
I20260812 06:19:16.340092  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000006 (ops 27-31)
I20260812 06:19:16.340123  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000007 (ops 32-36)
I20260812 06:19:16.340154  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000008 (ops 37-41)
I20260812 06:19:16.340184  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000009 (ops 42-46)
I20260812 06:19:16.340216  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000010 (ops 47-51)
I20260812 06:19:16.340245  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000011 (ops 52-56)
I20260812 06:19:16.340276  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000012 (ops 57-61)
I20260812 06:19:16.340306  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000013 (ops 62-66)
I20260812 06:19:16.362149  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: LogGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:19:16.362674  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=3.181125
I20260812 06:19:16.377851  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:16.378278  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e): 447 bytes on disk
I20260812 06:19:16.378718  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.379158  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:16.397673  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.018s	user 0.004s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3371,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.398083  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:16.628605  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.230s	user 0.141s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":861,"lbm_read_time_us":16183,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39036,"lbm_writes_lt_1ms":743,"mutex_wait_us":519,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:19:16.629590  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=15.087375
I20260812 06:19:16.686909  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.057s	user 0.033s	sys 0.022s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20054,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:16.687636  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=4.173312
I20260812 06:19:16.704373  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":5374414,"delete_count":0,"lbm_write_time_us":6899,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:19:16.704782  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=1.196750
I20260812 06:19:16.711563  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":2342,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:19:16.712009  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:16.922830  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.211s	user 0.134s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918175,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":859,"lbm_read_time_us":14099,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30596,"lbm_writes_lt_1ms":643,"mutex_wait_us":17,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3000}
I20260812 06:19:16.923406  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=18.063937
I20260812 06:19:16.987532  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.064s	user 0.034s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":22948,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:16.988068  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:16.998572  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.999090  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:17.190445  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.191s	user 0.125s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2302,"lbm_read_time_us":14487,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30467,"lbm_writes_lt_1ms":643,"mutex_wait_us":1930,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:19:17.191035  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:17.235338  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19388,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.235826  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:17.262322  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.026s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.262814  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:17.278066  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.278733  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:17.470970  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.192s	user 0.120s	sys 0.071s 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":530,"lbm_read_time_us":14473,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30870,"lbm_writes_lt_1ms":643,"mutex_wait_us":324,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":3000}
I20260812 06:19:17.471513  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:17.515456  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.516185  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:17.543045  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.027s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.543495  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:17.554018  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.554494  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:17.749033  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.194s	user 0.101s	sys 0.092s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918217,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2028,"lbm_read_time_us":13881,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31801,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:19:17.750581  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=15.087375
I20260812 06:19:17.786088  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.035s	user 0.012s	sys 0.020s Metrics: {"bytes_written":16697071,"delete_count":0,"lbm_write_time_us":15513,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2035}
I20260812 06:19:17.786610  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:17.798240  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:19:17.798789  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushMRSOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:17.832202  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushMRSOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1180,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1597,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:17.832850  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling LogGCOp(50ad6b44debf4caf969132985b698f7e): free 129773570 bytes of WAL
I20260812 06:19:17.833082  7969 log_reader.cc:385] T 50ad6b44debf4caf969132985b698f7e: removed 13 log segments from log reader
I20260812 06:19:17.833130  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000014 (ops 67-71)
I20260812 06:19:17.833158  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000015 (ops 72-76)
I20260812 06:19:17.833177  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000016 (ops 77-81)
I20260812 06:19:17.833220  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000017 (ops 82-86)
I20260812 06:19:17.833244  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000018 (ops 87-91)
I20260812 06:19:17.833271  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000019 (ops 92-96)
I20260812 06:19:17.833304  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000020 (ops 97-100)
I20260812 06:19:17.833335  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000021 (ops 101-105)
I20260812 06:19:17.833365  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000022 (ops 106-110)
I20260812 06:19:17.833395  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000023 (ops 111-115)
I20260812 06:19:17.833426  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000024 (ops 116-120)
I20260812 06:19:17.833456  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000025 (ops 121-125)
I20260812 06:19:17.833487  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000026 (ops 126-130)
I20260812 06:19:17.859107  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: LogGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:17.859506  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=5.165500
I20260812 06:19:17.879484  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.020s	user 0.006s	sys 0.013s Metrics: {"bytes_written":6564114,"delete_count":0,"lbm_write_time_us":8082,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:19:17.879993  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e): 490 bytes on disk
I20260812 06:19:17.880421  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:17.880983  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:17.887612  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1641152,"delete_count":0,"lbm_write_time_us":2043,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 06:19:17.888043  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:18.093102  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.205s	user 0.133s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":182,"lbm_read_time_us":15700,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36590,"lbm_writes_lt_1ms":743,"mutex_wait_us":37,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:19:18.093658  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=18.063937
I20260812 06:19:18.149318  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.055s	user 0.029s	sys 0.024s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24978,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:18.149845  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:18.161592  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.162060  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:18.328763  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.167s	user 0.140s	sys 0.026s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":12729,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33299,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:19:18.329411  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:18.411823  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.082s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":57655,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.412360  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:18.429158  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.429749  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:18.579355  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.149s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":10622,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26883,"lbm_writes_lt_1ms":543,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:19:18.580106  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:18.624051  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19243,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.624562  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:18.762684  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.138s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":136,"lbm_read_time_us":9003,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22848,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:19:18.763305  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=11.118625
I20260812 06:19:18.793509  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.030s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12687,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1550}
I20260812 06:19:18.794600  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:18.806897  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.807507  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:18.942210  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.135s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":878,"lbm_read_time_us":10419,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25510,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:19:18.942888  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=10.126437
I20260812 06:19:18.981858  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.039s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15922,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.982481  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:18.999889  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.000536  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:19.134825  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.134s	user 0.112s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1056,"lbm_read_time_us":8910,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25993,"lbm_writes_lt_1ms":443,"mutex_wait_us":369,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:19.135427  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=10.126437
I20260812 06:19:19.173743  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.038s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14931,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.174255  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:19.189421  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.190025  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushMRSOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:19.218611  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushMRSOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1223,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1348,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:19.219295  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling LogGCOp(50ad6b44debf4caf969132985b698f7e): free 115943382 bytes of WAL
I20260812 06:19:19.219512  7969 log_reader.cc:385] T 50ad6b44debf4caf969132985b698f7e: removed 11 log segments from log reader
I20260812 06:19:19.219560  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000027 (ops 131-135)
I20260812 06:19:19.219590  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000028 (ops 136-140)
I20260812 06:19:19.219621  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000029 (ops 141-145)
I20260812 06:19:19.219655  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000030 (ops 146-150)
I20260812 06:19:19.219678  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000031 (ops 151-155)
I20260812 06:19:19.219718  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000032 (ops 156-160)
I20260812 06:19:19.219753  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000033 (ops 161-165)
I20260812 06:19:19.219786  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000034 (ops 166-170)
I20260812 06:19:19.219818  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000035 (ops 171-175)
I20260812 06:19:19.219849  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000036 (ops 176-180)
I20260812 06:19:19.219882  7969 log.cc:1079] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: Deleting log segment in path: /tmp/dist-test-task7Dbefg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515546122038-7385-0/minicluster-data/ts-0-root/wals/50ad6b44debf4caf969132985b698f7e/wal-000000037 (ops 181-185)
I20260812 06:19:19.240410  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: LogGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.021s	user 0.001s	sys 0.018s Metrics: {}
I20260812 06:19:19.240880  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e): 447 bytes on disk
I20260812 06:19:19.241321  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: UndoDeltaBlockGCOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:19.241868  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:19.262192  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.262652  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:19.278038  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.278533  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:19.449085  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.170s	user 0.137s	sys 0.030s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":6315,"lbm_read_time_us":13205,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34603,"lbm_writes_lt_1ms":643,"mutex_wait_us":2710,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:19:19.450065  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=14.095187
I20260812 06:19:19.490190  7385 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.592s	user 1.682s	sys 0.123s
I20260812 06:19:19.493481  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.043s	user 0.028s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17041,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.493968  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e): perf score=2.188937
I20260812 06:19:19.510186  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: FlushDeltaMemStoresOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:19:19.510715  8096 maintenance_manager.cc:419] P 9171940a3fd44ecbb049da3afb04afb6: Scheduling MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e): perf score=1.000000
I20260812 06:19:19.538656  7385 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.048s	user 0.004s	sys 0.000s
I20260812 06:19:19.539269  7385 tablet_server.cc:179] TabletServer@127.7.54.65:0 shutting down...
I20260812 06:19:19.618304  7969 maintenance_manager.cc:643] P 9171940a3fd44ecbb049da3afb04afb6: MajorDeltaCompactionOp(50ad6b44debf4caf969132985b698f7e) complete. Timing: real 0.107s	user 0.095s	sys 0.012s Metrics: {"cfile_cache_hit":401,"cfile_cache_hit_bytes":16409767,"cfile_cache_miss":131,"cfile_cache_miss_bytes":8405916,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1217,"lbm_read_time_us":3334,"lbm_reads_lt_1ms":163,"lbm_write_time_us":23646,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:19.618921  7385 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:19.619145  7385 tablet_replica.cc:333] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6: stopping tablet replica
I20260812 06:19:19.619287  7385 raft_consensus.cc:2243] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:19.619448  7385 raft_consensus.cc:2272] T 50ad6b44debf4caf969132985b698f7e P 9171940a3fd44ecbb049da3afb04afb6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:19.623775  7385 tablet_server.cc:196] TabletServer@127.7.54.65:0 shutdown complete.
I20260812 06:19:19.662951  7385 master.cc:562] Master@127.7.54.126:42841 shutting down...
I20260812 06:19:19.666591  7385 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:19.666774  7385 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:19.666850  7385 tablet_replica.cc:333] T 00000000000000000000000000000000 P 01bad2f77d8b40988dab6354a0525a2c: stopping tablet replica
I20260812 06:19:19.678963  7385 master.cc:584] Master@127.7.54.126:42841 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5084 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13625 ms total)

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