[==========] 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:01.309018 17427 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.4.254:45181
I20260812 06:19:01.310573 17427 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:01.311656 17427 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.322741 17436 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:01.322791 17427 server_base.cc:1061] running on GCE node
W20260812 06:19:01.323282 17438 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:01.323401 17435 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:01.324247 17427 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.324414 17427 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:01.324465 17427 hybrid_clock.cc:648] HybridClock initialized: now 1786515541324461 us; error 0 us; skew 500 ppm
I20260812 06:19:01.327479 17427 webserver.cc:533] Webserver started at http://127.17.4.254:36255/ using document root <none> and password file <none>
I20260812 06:19:01.328434 17427 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.328568 17427 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.328917 17427 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.331910 17427 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/master-0-root/instance:
uuid: "0af892d629cf4f5a9513c9062130b6ab"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-7z32"
I20260812 06:19:01.338764 17427 fs_manager.cc:696] Time spent creating directory manager: real 0.006s	user 0.002s	sys 0.004s
I20260812 06:19:01.342563 17447 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:01.344494 17427 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:19:01.344714 17427 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/master-0-root
uuid: "0af892d629cf4f5a9513c9062130b6ab"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-7z32"
I20260812 06:19:01.344874 17427 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-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:01.364339 17427 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.365410 17427 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:01.365666 17427 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.377210 17427 rpc_server.cc:307] RPC server started. Bound to: 127.17.4.254:45181
I20260812 06:19:01.377210 17533 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.4.254:45181 every 8 connection(s)
I20260812 06:19:01.380993 17535 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:01.394116 17535 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: Bootstrap starting.
I20260812 06:19:01.398727 17535 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.400718 17535 log.cc:826] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:01.404295 17535 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: No bootstrap required, opened a new log
I20260812 06:19:01.409950 17535 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0af892d629cf4f5a9513c9062130b6ab" member_type: VOTER }
I20260812 06:19:01.410382 17535 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.410462 17535 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0af892d629cf4f5a9513c9062130b6ab, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.411782 17535 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [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: "0af892d629cf4f5a9513c9062130b6ab" member_type: VOTER }
I20260812 06:19:01.412058 17535 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.412143 17535 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.412312 17535 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.413873 17535 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0af892d629cf4f5a9513c9062130b6ab" member_type: VOTER }
I20260812 06:19:01.414659 17535 leader_election.cc:304] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [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: 0af892d629cf4f5a9513c9062130b6ab; no voters: 
I20260812 06:19:01.415246 17535 leader_election.cc:290] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.415642 17538 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.416087 17538 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 1 LEADER]: Becoming Leader. State: Replica: 0af892d629cf4f5a9513c9062130b6ab, State: Running, Role: LEADER
I20260812 06:19:01.416877 17535 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:01.416903 17538 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [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: "0af892d629cf4f5a9513c9062130b6ab" member_type: VOTER }
I20260812 06:19:01.419950 17427 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:01.420080 17539 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0af892d629cf4f5a9513c9062130b6ab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0af892d629cf4f5a9513c9062130b6ab" member_type: VOTER } }
I20260812 06:19:01.420261 17539 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:01.420674 17540 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0af892d629cf4f5a9513c9062130b6ab. Latest consensus state: current_term: 1 leader_uuid: "0af892d629cf4f5a9513c9062130b6ab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0af892d629cf4f5a9513c9062130b6ab" member_type: VOTER } }
I20260812 06:19:01.420759 17540 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:01.423481 17563 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:01.423642 17563 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:01.423776 17564 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:01.424747 17564 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:01.432250 17564 catalog_manager.cc:1383] Generated new cluster ID: c68968d95a0a4f1a94d55b4ada3ca352
I20260812 06:19:01.432359 17564 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:01.451099 17564 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:01.452358 17564 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:01.463933 17564 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: Generated new TSK 0
I20260812 06:19:01.464846 17564 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:01.485323 17427 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:01.489969 17427 server_base.cc:1061] running on GCE node
W20260812 06:19:01.489856 17573 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:01.489683 17575 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:01.489787 17571 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:01.490775 17427 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.490918 17427 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:01.490952 17427 hybrid_clock.cc:648] HybridClock initialized: now 1786515541490951 us; error 0 us; skew 500 ppm
I20260812 06:19:01.492379 17427 webserver.cc:533] Webserver started at http://127.17.4.193:40135/ using document root <none> and password file <none>
I20260812 06:19:01.492599 17427 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.492671 17427 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.492756 17427 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.493328 17427 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/instance:
uuid: "cc4a744424884b31a320407da3e3f58b"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-7z32"
I20260812 06:19:01.495723 17427 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:01.497319 17586 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:01.497741 17427 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:01.497862 17427 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root
uuid: "cc4a744424884b31a320407da3e3f58b"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-7z32"
I20260812 06:19:01.497977 17427 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-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:01.509220 17427 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.509932 17427 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.510618 17427 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:01.512092 17427 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:01.512187 17427 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.512260 17427 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:01.512301 17427 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.521862 17427 rpc_server.cc:307] RPC server started. Bound to: 127.17.4.193:42125
I20260812 06:19:01.521984 17688 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.4.193:42125 every 8 connection(s)
I20260812 06:19:01.536764 17690 heartbeater.cc:344] Connected to a master server at 127.17.4.254:45181
I20260812 06:19:01.537155 17690 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:01.537866 17690 heartbeater.cc:507] Master 127.17.4.254:45181 requested a full tablet report, sending...
I20260812 06:19:01.540233 17476 ts_manager.cc:194] Registered new tserver with Master: cc4a744424884b31a320407da3e3f58b (127.17.4.193:42125)
I20260812 06:19:01.540987 17427 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01814849s
I20260812 06:19:01.542055 17476 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49610
I20260812 06:19:01.557411 17476 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49624:
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:01.581192 17628 tablet_service.cc:1511] Processing CreateTablet for tablet 7861c9a51a3642bd9c61459a90a9ee5f (DEFAULT_TABLE table=heavy-update-compaction-test [id=fd29eadcf03e4446ab457188ed1b9c28]), partition=
I20260812 06:19:01.581799 17628 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7861c9a51a3642bd9c61459a90a9ee5f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:01.584465 17711 tablet_bootstrap.cc:492] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Bootstrap starting.
I20260812 06:19:01.585629 17711 tablet_bootstrap.cc:654] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.587337 17711 tablet_bootstrap.cc:492] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: No bootstrap required, opened a new log
I20260812 06:19:01.587477 17711 ts_tablet_manager.cc:1403] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:01.588088 17711 raft_consensus.cc:359] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc4a744424884b31a320407da3e3f58b" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 42125 } }
I20260812 06:19:01.588219 17711 raft_consensus.cc:385] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.588253 17711 raft_consensus.cc:740] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cc4a744424884b31a320407da3e3f58b, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.588409 17711 consensus_queue.cc:260] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [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: "cc4a744424884b31a320407da3e3f58b" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 42125 } }
I20260812 06:19:01.588492 17711 raft_consensus.cc:399] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.588532 17711 raft_consensus.cc:493] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.588574 17711 raft_consensus.cc:3060] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.589666 17711 raft_consensus.cc:515] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc4a744424884b31a320407da3e3f58b" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 42125 } }
I20260812 06:19:01.589829 17711 leader_election.cc:304] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [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: cc4a744424884b31a320407da3e3f58b; no voters: 
I20260812 06:19:01.590061 17711 leader_election.cc:290] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.590341 17715 raft_consensus.cc:2804] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.590703 17715 raft_consensus.cc:697] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 1 LEADER]: Becoming Leader. State: Replica: cc4a744424884b31a320407da3e3f58b, State: Running, Role: LEADER
I20260812 06:19:01.590809 17690 heartbeater.cc:499] Master 127.17.4.254:45181 was elected leader, sending a full tablet report...
I20260812 06:19:01.591050 17715 consensus_queue.cc:237] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [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: "cc4a744424884b31a320407da3e3f58b" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 42125 } }
I20260812 06:19:01.590405 17711 ts_tablet_manager.cc:1434] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:01.595220 17476 catalog_manager.cc:5719] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b reported cstate change: term changed from 0 to 1, leader changed from <none> to cc4a744424884b31a320407da3e3f58b (127.17.4.193). New cstate: current_term: 1 leader_uuid: "cc4a744424884b31a320407da3e3f58b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cc4a744424884b31a320407da3e3f58b" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 42125 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:01.689797 17427 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.085s	user 0.020s	sys 0.020s
I20260812 06:19:01.773404 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.156503
I20260812 06:19:01.915669 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.142s	user 0.102s	sys 0.028s Metrics: {"bytes_written":4512900,"cfile_init":1,"compiler_manager_pool.queue_time_us":336,"delete_count":0,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1378,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":26030,"lbm_writes_lt_1ms":367,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"thread_start_us":196,"threads_started":1,"update_count":550}
I20260812 06:19:01.917294 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f): free 11976772 bytes of WAL
I20260812 06:19:01.917748 17595 log_reader.cc:385] T 7861c9a51a3642bd9c61459a90a9ee5f: removed 1 log segments from log reader
I20260812 06:19:01.917878 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000001 (ops 1-6)
I20260812 06:19:01.922210 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:01.922915 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f): 8206528 bytes on disk
I20260812 06:19:01.923914 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.924479 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:01.943836 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7460,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.944554 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:02.078186 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.133s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":232,"cfile_cache_miss_bytes":12344544,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":529,"lbm_read_time_us":5779,"lbm_reads_lt_1ms":264,"lbm_write_time_us":18489,"lbm_writes_lt_1ms":243,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":375,"threads_started":5,"update_count":1000}
I20260812 06:19:02.079080 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:02.118158 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.039s	user 0.010s	sys 0.020s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13945,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:19:02.118924 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:02.239158 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.120s	user 0.084s	sys 0.028s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12344439,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":298,"lbm_read_time_us":5869,"lbm_reads_lt_1ms":263,"lbm_write_time_us":20404,"lbm_writes_lt_1ms":243,"peak_mem_usage":25836184,"reinsert_count":0,"update_count":1000}
I20260812 06:19:02.239959 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=7.149875
I20260812 06:19:02.269595 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.029s	user 0.010s	sys 0.016s Metrics: {"bytes_written":8615336,"delete_count":0,"lbm_write_time_us":13481,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:02.270382 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:02.285588 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5878,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.286211 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:02.431290 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.145s	user 0.095s	sys 0.044s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446974,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"dirs.run_cpu_time_us":617,"dirs.run_wall_time_us":3785,"lbm_read_time_us":9063,"lbm_reads_lt_1ms":372,"lbm_write_time_us":27655,"lbm_writes_lt_1ms":343,"mutex_wait_us":4,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":1500}
I20260812 06:19:02.432307 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:02.485127 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.052s	user 0.044s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20696,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.485816 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:02.509732 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.024s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.510321 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:02.742074 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.231s	user 0.163s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549383,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":598,"lbm_read_time_us":12968,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34359,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.742887 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:02.803818 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.061s	user 0.032s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22718,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.804562 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:02.937124 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.132s	user 0.074s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446851,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":7769,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23570,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:19:02.937789 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:02.991063 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.053s	user 0.032s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.991847 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:03.154315 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.162s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446851,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":300,"lbm_read_time_us":10170,"lbm_reads_lt_1ms":363,"lbm_write_time_us":29596,"lbm_writes_lt_1ms":343,"mutex_wait_us":100,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:19:03.155113 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=11.118625
I20260812 06:19:03.230171 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.074s	user 0.039s	sys 0.017s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":27963,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:03.231308 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:03.273051 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.041s	user 0.018s	sys 0.019s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":12017,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:03.274703 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:03.291321 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":1395005,"delete_count":0,"lbm_write_time_us":3695,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:19:03.291981 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.196750
I20260812 06:19:03.303717 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:19:03.304417 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:03.585707 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.281s	user 0.188s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28754357,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1110,"lbm_read_time_us":16338,"lbm_reads_lt_1ms":674,"lbm_write_time_us":57001,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":3000}
I20260812 06:19:03.586736 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=14.095187
I20260812 06:19:03.656075 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.069s	user 0.034s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23507,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.656998 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:03.675649 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.676843 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:03.717935 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.041s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":124,"dirs.run_cpu_time_us":662,"dirs.run_wall_time_us":2454,"drs_written":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1634,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:03.719300 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:03.942350 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.223s	user 0.149s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1255,"lbm_read_time_us":15701,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33642,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:03.944536 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f): free 112692365 bytes of WAL
I20260812 06:19:03.945032 17595 log_reader.cc:385] T 7861c9a51a3642bd9c61459a90a9ee5f: removed 11 log segments from log reader
I20260812 06:19:03.945107 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000002 (ops 7-11)
I20260812 06:19:03.945163 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000003 (ops 12-16)
I20260812 06:19:03.945196 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000004 (ops 17-21)
I20260812 06:19:03.945226 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000005 (ops 22-26)
I20260812 06:19:03.945346 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000006 (ops 27-31)
I20260812 06:19:03.945393 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000007 (ops 32-36)
I20260812 06:19:03.945432 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000008 (ops 37-41)
I20260812 06:19:03.945472 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000009 (ops 42-46)
I20260812 06:19:03.945504 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000010 (ops 47-51)
I20260812 06:19:03.945544 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000011 (ops 52-56)
I20260812 06:19:03.945580 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000012 (ops 57-61)
I20260812 06:19:03.985322 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.040s	user 0.001s	sys 0.033s Metrics: {}
I20260812 06:19:03.985817 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f): 462 bytes on disk
I20260812 06:19:03.986406 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.987224 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=15.087375
I20260812 06:19:04.046746 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.059s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":21526,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:04.047463 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:04.062155 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5195,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.063150 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:04.295672 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.232s	user 0.149s	sys 0.081s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651782,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1394,"lbm_read_time_us":18750,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39812,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:04.296778 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=14.095187
I20260812 06:19:04.378278 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.081s	user 0.028s	sys 0.044s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":32670,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.379446 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=4.173312
I20260812 06:19:04.399590 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.020s	user 0.011s	sys 0.008s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":8282,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:19:04.400445 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.196750
I20260812 06:19:04.417281 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":5795,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:04.418632 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:04.664346 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.245s	user 0.149s	sys 0.095s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754300,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":872,"lbm_read_time_us":19734,"lbm_reads_lt_1ms":665,"lbm_write_time_us":42955,"lbm_writes_lt_1ms":643,"mutex_wait_us":89,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:04.665421 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=14.095187
I20260812 06:19:04.743986 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.078s	user 0.037s	sys 0.039s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27897,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.745167 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:04.758453 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.759085 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:04.958585 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.199s	user 0.150s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1080,"lbm_read_time_us":17159,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35226,"lbm_writes_lt_1ms":543,"mutex_wait_us":139,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.959182 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:05.008605 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.049s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19937,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.009522 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:05.163235 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.153s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446853,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":440,"lbm_read_time_us":10089,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24835,"lbm_writes_lt_1ms":343,"mutex_wait_us":97,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.164492 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:05.221248 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.056s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18107,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.222095 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:05.240041 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.241153 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:05.417382 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.176s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549383,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1345,"lbm_read_time_us":11988,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34447,"lbm_writes_lt_1ms":443,"mutex_wait_us":401,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.418545 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:05.465312 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.046s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21122,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.465902 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:05.622361 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.156s	user 0.091s	sys 0.056s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446853,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":912,"lbm_read_time_us":13482,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22824,"lbm_writes_lt_1ms":343,"mutex_wait_us":381,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:19:05.623208 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=7.149875
I20260812 06:19:05.656203 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.033s	user 0.016s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14732,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:05.656795 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:05.668687 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4572,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.669269 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:05.709065 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.040s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":134,"dirs.run_cpu_time_us":521,"dirs.run_wall_time_us":1947,"drs_written":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1696,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:05.709908 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f): free 124257256 bytes of WAL
I20260812 06:19:05.710156 17595 log_reader.cc:385] T 7861c9a51a3642bd9c61459a90a9ee5f: removed 12 log segments from log reader
I20260812 06:19:05.710203 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000013 (ops 62-66)
I20260812 06:19:05.710242 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000014 (ops 67-70)
I20260812 06:19:05.710311 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000015 (ops 71-75)
I20260812 06:19:05.710367 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000016 (ops 76-80)
I20260812 06:19:05.710418 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000017 (ops 81-85)
I20260812 06:19:05.710467 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000018 (ops 86-90)
I20260812 06:19:05.710513 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000019 (ops 91-95)
I20260812 06:19:05.710559 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000020 (ops 96-100)
I20260812 06:19:05.710602 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000021 (ops 101-105)
I20260812 06:19:05.710646 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000022 (ops 106-110)
I20260812 06:19:05.710690 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000023 (ops 111-115)
I20260812 06:19:05.710736 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000024 (ops 116-120)
I20260812 06:19:05.740314 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:05.740917 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:05.765728 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.025s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.766336 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:05.778788 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.779475 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:05.955634 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.176s	user 0.116s	sys 0.056s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24652023,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2035,"lbm_read_time_us":12616,"lbm_reads_lt_1ms":574,"lbm_write_time_us":36909,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":645,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":51456,"thread_start_us":125,"threads_started":1,"update_count":2500}
I20260812 06:19:05.956802 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:06.015445 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.058s	user 0.030s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.016435 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f): 463 bytes on disk
I20260812 06:19:06.017069 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.017632 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:06.033228 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.034204 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:06.199628 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.165s	user 0.124s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":914,"lbm_read_time_us":12462,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31720,"lbm_writes_lt_1ms":443,"mutex_wait_us":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:19:06.200429 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:06.249997 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.048s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20905,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.250924 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:06.264456 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.265506 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:06.401446 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.136s	user 0.120s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":412,"lbm_read_time_us":9498,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25480,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.402284 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=7.149875
I20260812 06:19:06.434638 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.032s	user 0.018s	sys 0.011s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13704,"lbm_writes_lt_1ms":213,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1050}
I20260812 06:19:06.435417 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:06.463158 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.027s	user 0.007s	sys 0.020s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5083,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.463783 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:06.607752 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.144s	user 0.086s	sys 0.053s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446961,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":12142,"lbm_read_time_us":12013,"lbm_reads_lt_1ms":372,"lbm_write_time_us":20145,"lbm_writes_lt_1ms":343,"mutex_wait_us":3959,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":1500}
I20260812 06:19:06.608852 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:06.644207 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.034s	user 0.023s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12458,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:19:06.644869 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:06.657678 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.658382 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:06.776533 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.118s	user 0.090s	sys 0.027s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446970,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1209,"lbm_read_time_us":9125,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21120,"lbm_writes_lt_1ms":343,"mutex_wait_us":138,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":32000,"update_count":1500}
I20260812 06:19:06.777433 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:06.830402 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.053s	user 0.018s	sys 0.016s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":17829,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:06.831383 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:06.853905 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.022s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.854638 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:06.989723 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.135s	user 0.093s	sys 0.041s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446969,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":14484,"lbm_reads_lt_1ms":372,"lbm_write_time_us":21209,"lbm_writes_lt_1ms":343,"mutex_wait_us":122,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.990564 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:07.033296 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.043s	user 0.026s	sys 0.007s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":15386,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:07.034003 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:07.047711 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.048281 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:07.167022 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.119s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446971,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":651,"lbm_read_time_us":9317,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23182,"lbm_writes_lt_1ms":343,"mutex_wait_us":121,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":1500}
I20260812 06:19:07.167783 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:07.196973 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.029s	user 0.026s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12326,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:07.197934 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:07.294286 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.096s	user 0.071s	sys 0.020s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12344439,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":939,"lbm_read_time_us":5921,"lbm_reads_lt_1ms":263,"lbm_write_time_us":15758,"lbm_writes_lt_1ms":243,"mutex_wait_us":136,"peak_mem_usage":25836184,"reinsert_count":0,"update_count":1000}
I20260812 06:19:07.295234 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:07.333828 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.038s	user 0.021s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14647,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:07.335196 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:07.429816 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.094s	user 0.078s	sys 0.015s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12344439,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":654,"lbm_read_time_us":6070,"lbm_reads_lt_1ms":263,"lbm_write_time_us":17453,"lbm_writes_lt_1ms":243,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1000}
I20260812 06:19:07.430562 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:07.468963 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.038s	user 0.025s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14518,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:19:07.469753 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:07.493320 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.494163 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:07.540833 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushMRSOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.046s	user 0.037s	sys 0.004s Metrics: {"bytes_written":1193506,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":314,"dirs.run_wall_time_us":1659,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2195,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:07.541801 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f): free 121006656 bytes of WAL
I20260812 06:19:07.542086 17595 log_reader.cc:385] T 7861c9a51a3642bd9c61459a90a9ee5f: removed 12 log segments from log reader
I20260812 06:19:07.542136 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000025 (ops 121-125)
I20260812 06:19:07.542173 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000026 (ops 126-130)
I20260812 06:19:07.542253 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000027 (ops 131-135)
I20260812 06:19:07.542310 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000028 (ops 136-140)
I20260812 06:19:07.542364 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000029 (ops 141-145)
I20260812 06:19:07.542428 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000030 (ops 146-150)
I20260812 06:19:07.542462 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000031 (ops 151-154)
I20260812 06:19:07.542484 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000032 (ops 155-159)
I20260812 06:19:07.542503 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000033 (ops 160-164)
I20260812 06:19:07.542521 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000034 (ops 165-169)
I20260812 06:19:07.542582 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000035 (ops 170-174)
I20260812 06:19:07.542630 17595 log.cc:1079] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/7861c9a51a3642bd9c61459a90a9ee5f/wal-000000036 (ops 175-179)
I20260812 06:19:07.578099 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: LogGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.036s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:19:07.578707 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f): 463 bytes on disk
I20260812 06:19:07.579377 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: UndoDeltaBlockGCOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.580173 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:07.596921 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.597546 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:07.612581 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5326,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.613193 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:07.806900 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.193s	user 0.141s	sys 0.051s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24652032,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2719,"lbm_read_time_us":14370,"lbm_reads_lt_1ms":574,"lbm_write_time_us":34621,"lbm_writes_lt_1ms":543,"mutex_wait_us":1238,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":96896,"thread_start_us":134,"threads_started":1,"update_count":2500}
I20260812 06:19:07.807966 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=10.126437
I20260812 06:19:07.880219 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.072s	user 0.018s	sys 0.045s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":26056,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.880812 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:07.892334 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.892992 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:08.057219 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.164s	user 0.107s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549383,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2479,"lbm_read_time_us":12371,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25146,"lbm_writes_lt_1ms":443,"mutex_wait_us":668,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.058145 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=7.149875
I20260812 06:19:08.102432 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.044s	user 0.021s	sys 0.020s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":18761,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1050}
I20260812 06:19:08.103351 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:08.136512 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.033s	user 0.006s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7650,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.137141 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=2.188937
I20260812 06:19:08.157545 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.158560 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=1.000000
I20260812 06:19:08.242185 17427 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.552s	user 2.348s	sys 0.144s
I20260812 06:19:08.321354 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: MajorDeltaCompactionOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.162s	user 0.137s	sys 0.024s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20549493,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1239,"lbm_read_time_us":13795,"lbm_reads_lt_1ms":469,"lbm_write_time_us":29590,"lbm_writes_lt_1ms":443,"mutex_wait_us":523,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":2000}
I20260812 06:19:08.322271 17694 maintenance_manager.cc:419] P cc4a744424884b31a320407da3e3f58b: Scheduling FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f): perf score=6.157687
I20260812 06:19:08.323900 17427 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.004s	sys 0.000s
I20260812 06:19:08.324705 17427 tablet_server.cc:179] TabletServer@127.17.4.193:0 shutting down...
I20260812 06:19:08.351481 17595 maintenance_manager.cc:643] P cc4a744424884b31a320407da3e3f58b: FlushDeltaMemStoresOp(7861c9a51a3642bd9c61459a90a9ee5f) complete. Timing: real 0.029s	user 0.012s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12402,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:08.352536 17427 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:08.353024 17427 tablet_replica.cc:333] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b: stopping tablet replica
I20260812 06:19:08.353271 17427 raft_consensus.cc:2243] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.353495 17427 raft_consensus.cc:2272] T 7861c9a51a3642bd9c61459a90a9ee5f P cc4a744424884b31a320407da3e3f58b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.370383 17427 tablet_server.cc:196] TabletServer@127.17.4.193:0 shutdown complete.
I20260812 06:19:08.376897 17427 master.cc:562] Master@127.17.4.254:45181 shutting down...
I20260812 06:19:08.383592 17427 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.383903 17427 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.383997 17427 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0af892d629cf4f5a9513c9062130b6ab: stopping tablet replica
I20260812 06:19:08.397713 17427 master.cc:584] Master@127.17.4.254:45181 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (7208 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:08.516567 17427 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.4.254:39833
I20260812 06:19:08.517088 17427 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:08.520063 17427 server_base.cc:1061] running on GCE node
W20260812 06:19:08.520255 17755 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:08.520323 17758 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:08.520265 17754 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:08.520695 17427 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:08.520771 17427 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:08.520807 17427 hybrid_clock.cc:648] HybridClock initialized: now 1786515548520807 us; error 0 us; skew 500 ppm
I20260812 06:19:08.521947 17427 webserver.cc:533] Webserver started at http://127.17.4.254:37415/ using document root <none> and password file <none>
I20260812 06:19:08.522162 17427 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:08.522239 17427 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:08.522358 17427 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:08.522900 17427 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/master-0-root/instance:
uuid: "ecab92acf0274b60a68967bcde57a890"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-7z32"
I20260812 06:19:08.524718 17427 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:19:08.526068 17766 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:08.526572 17427 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:08.526692 17427 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/master-0-root
uuid: "ecab92acf0274b60a68967bcde57a890"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-7z32"
I20260812 06:19:08.526799 17427 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-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:08.559062 17427 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:08.559634 17427 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:08.565043 17427 rpc_server.cc:307] RPC server started. Bound to: 127.17.4.254:39833
I20260812 06:19:08.566741 17856 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:08.567322 17853 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.4.254:39833 every 8 connection(s)
I20260812 06:19:08.584141 17856 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890: Bootstrap starting.
I20260812 06:19:08.585572 17856 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:08.587463 17856 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890: No bootstrap required, opened a new log
I20260812 06:19:08.588132 17856 raft_consensus.cc:359] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecab92acf0274b60a68967bcde57a890" member_type: VOTER }
I20260812 06:19:08.588269 17856 raft_consensus.cc:385] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:08.588297 17856 raft_consensus.cc:740] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ecab92acf0274b60a68967bcde57a890, State: Initialized, Role: FOLLOWER
I20260812 06:19:08.588495 17856 consensus_queue.cc:260] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [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: "ecab92acf0274b60a68967bcde57a890" member_type: VOTER }
I20260812 06:19:08.588603 17856 raft_consensus.cc:399] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:08.588644 17856 raft_consensus.cc:493] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:08.588724 17856 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:08.590286 17856 raft_consensus.cc:515] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecab92acf0274b60a68967bcde57a890" member_type: VOTER }
I20260812 06:19:08.590632 17856 leader_election.cc:304] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [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: ecab92acf0274b60a68967bcde57a890; no voters: 
I20260812 06:19:08.590981 17856 leader_election.cc:290] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:08.591289 17860 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:08.591603 17860 raft_consensus.cc:697] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 1 LEADER]: Becoming Leader. State: Replica: ecab92acf0274b60a68967bcde57a890, State: Running, Role: LEADER
I20260812 06:19:08.591745 17856 sys_catalog.cc:565] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:08.591922 17860 consensus_queue.cc:237] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [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: "ecab92acf0274b60a68967bcde57a890" member_type: VOTER }
I20260812 06:19:08.592622 17871 sys_catalog.cc:455] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ecab92acf0274b60a68967bcde57a890. Latest consensus state: current_term: 1 leader_uuid: "ecab92acf0274b60a68967bcde57a890" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecab92acf0274b60a68967bcde57a890" member_type: VOTER } }
I20260812 06:19:08.592744 17871 sys_catalog.cc:458] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:08.592898 17870 sys_catalog.cc:455] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ecab92acf0274b60a68967bcde57a890" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecab92acf0274b60a68967bcde57a890" member_type: VOTER } }
I20260812 06:19:08.592984 17870 sys_catalog.cc:458] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:08.593595 17882 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:08.594480 17882 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:08.594774 17427 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:08.597885 17882 catalog_manager.cc:1383] Generated new cluster ID: e54b32e7a43047bbad40ce55af58c7e9
I20260812 06:19:08.598002 17882 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:08.619210 17882 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:08.620085 17882 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:08.630563 17882 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890: Generated new TSK 0
I20260812 06:19:08.630996 17882 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:08.660475 17427 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:08.663408 17905 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:08.663472 17898 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:08.663540 17427 server_base.cc:1061] running on GCE node
W20260812 06:19:08.663687 17901 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:08.664003 17427 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:08.664079 17427 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:08.664098 17427 hybrid_clock.cc:648] HybridClock initialized: now 1786515548664099 us; error 0 us; skew 500 ppm
I20260812 06:19:08.665169 17427 webserver.cc:533] Webserver started at http://127.17.4.193:33019/ using document root <none> and password file <none>
I20260812 06:19:08.665390 17427 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:08.665455 17427 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:08.665616 17427 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:08.666085 17427 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/instance:
uuid: "198383cc91f341bd894d22cc0c156ae1"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-7z32"
I20260812 06:19:08.668081 17427 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:08.669468 17911 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:08.669930 17427 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:08.670043 17427 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root
uuid: "198383cc91f341bd894d22cc0c156ae1"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-7z32"
I20260812 06:19:08.670183 17427 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-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:08.684728 17427 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:08.685232 17427 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:08.685606 17427 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:08.686169 17427 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:08.686216 17427 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.686254 17427 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:08.686321 17427 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.691648 17427 rpc_server.cc:307] RPC server started. Bound to: 127.17.4.193:36107
I20260812 06:19:08.691764 18011 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.4.193:36107 every 8 connection(s)
I20260812 06:19:08.704811 18013 heartbeater.cc:344] Connected to a master server at 127.17.4.254:39833
I20260812 06:19:08.705024 18013 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:08.705453 18013 heartbeater.cc:507] Master 127.17.4.254:39833 requested a full tablet report, sending...
I20260812 06:19:08.706671 17791 ts_manager.cc:194] Registered new tserver with Master: 198383cc91f341bd894d22cc0c156ae1 (127.17.4.193:36107)
I20260812 06:19:08.707211 17427 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014993373s
I20260812 06:19:08.707775 17791 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34458
I20260812 06:19:08.718549 17791 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34472:
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:08.731228 17954 tablet_service.cc:1511] Processing CreateTablet for tablet 614114f7388b41e3ba5338603f0569da (DEFAULT_TABLE table=heavy-update-compaction-test [id=be07187eea3a40d5b5cd110139c2316f]), partition=
I20260812 06:19:08.731556 17954 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 614114f7388b41e3ba5338603f0569da. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:08.734500 18037 tablet_bootstrap.cc:492] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Bootstrap starting.
I20260812 06:19:08.736135 18037 tablet_bootstrap.cc:654] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:08.738021 18037 tablet_bootstrap.cc:492] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: No bootstrap required, opened a new log
I20260812 06:19:08.738147 18037 ts_tablet_manager.cc:1403] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:19:08.738698 18037 raft_consensus.cc:359] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "198383cc91f341bd894d22cc0c156ae1" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 36107 } }
I20260812 06:19:08.738917 18037 raft_consensus.cc:385] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:08.738946 18037 raft_consensus.cc:740] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 198383cc91f341bd894d22cc0c156ae1, State: Initialized, Role: FOLLOWER
I20260812 06:19:08.739078 18037 consensus_queue.cc:260] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [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: "198383cc91f341bd894d22cc0c156ae1" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 36107 } }
I20260812 06:19:08.739147 18037 raft_consensus.cc:399] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:08.739171 18037 raft_consensus.cc:493] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:08.739202 18037 raft_consensus.cc:3060] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:08.740159 18037 raft_consensus.cc:515] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "198383cc91f341bd894d22cc0c156ae1" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 36107 } }
I20260812 06:19:08.740387 18037 leader_election.cc:304] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [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: 198383cc91f341bd894d22cc0c156ae1; no voters: 
I20260812 06:19:08.740695 18037 leader_election.cc:290] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:08.740963 18039 raft_consensus.cc:2804] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:08.741258 18037 ts_tablet_manager.cc:1434] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:08.741542 18013 heartbeater.cc:499] Master 127.17.4.254:39833 was elected leader, sending a full tablet report...
I20260812 06:19:08.741575 18039 raft_consensus.cc:697] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 1 LEADER]: Becoming Leader. State: Replica: 198383cc91f341bd894d22cc0c156ae1, State: Running, Role: LEADER
I20260812 06:19:08.741781 18039 consensus_queue.cc:237] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [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: "198383cc91f341bd894d22cc0c156ae1" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 36107 } }
I20260812 06:19:08.743480 17791 catalog_manager.cc:5719] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 198383cc91f341bd894d22cc0c156ae1 (127.17.4.193). New cstate: current_term: 1 leader_uuid: "198383cc91f341bd894d22cc0c156ae1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "198383cc91f341bd894d22cc0c156ae1" member_type: VOTER last_known_addr { host: "127.17.4.193" port: 36107 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:08.816075 17427 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.067s	user 0.017s	sys 0.008s
I20260812 06:19:08.943248 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushMRSOp(614114f7388b41e3ba5338603f0569da): perf score=13.101815
I20260812 06:19:09.119051 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushMRSOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.175s	user 0.130s	sys 0.024s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":121,"dirs.run_cpu_time_us":394,"dirs.run_wall_time_us":1105,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47132,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":556,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1000}
I20260812 06:19:09.120096 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling LogGCOp(614114f7388b41e3ba5338603f0569da): free 20290830 bytes of WAL
I20260812 06:19:09.120486 17918 log_reader.cc:385] T 614114f7388b41e3ba5338603f0569da: removed 2 log segments from log reader
I20260812 06:19:09.120579 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000001 (ops 1-6)
I20260812 06:19:09.120623 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000002 (ops 7-10)
I20260812 06:19:09.126703 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: LogGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:09.127525 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:09.144223 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6515,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.144843 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:09.291045 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.146s	user 0.104s	sys 0.041s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1895,"lbm_read_time_us":12209,"lbm_reads_lt_1ms":368,"lbm_write_time_us":26297,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":528,"threads_started":5,"update_count":1500}
I20260812 06:19:09.292518 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:09.342319 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.050s	user 0.029s	sys 0.010s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19174,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.343550 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da): 12308958 bytes on disk
I20260812 06:19:09.344370 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":115,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.345108 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:09.371557 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.372185 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:09.599145 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.227s	user 0.151s	sys 0.070s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1156,"lbm_read_time_us":17396,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34843,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:09.600067 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=11.118625
I20260812 06:19:09.646238 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.046s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21172,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:09.647670 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:09.669350 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.021s	user 0.016s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6582,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.670128 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:09.844761 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.174s	user 0.119s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":11630,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31826,"lbm_writes_lt_1ms":443,"mutex_wait_us":388,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26112,"update_count":2000}
I20260812 06:19:09.845679 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=14.095187
I20260812 06:19:09.907009 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.061s	user 0.051s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26919,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.907931 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:09.923936 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.924606 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:10.099174 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.174s	user 0.131s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":534,"lbm_read_time_us":12402,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31679,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:19:10.100028 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:10.156808 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.057s	user 0.051s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":25424,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.157575 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:10.301779 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.144s	user 0.071s	sys 0.064s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2021,"lbm_read_time_us":8946,"lbm_reads_lt_1ms":367,"lbm_write_time_us":24040,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.303108 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:10.363339 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.060s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22330,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.364451 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:10.380394 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.381083 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:10.560941 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.180s	user 0.135s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":12628,"lbm_reads_lt_1ms":464,"lbm_write_time_us":37751,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:10.562232 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:10.612001 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.049s	user 0.034s	sys 0.013s Metrics: {"bytes_written":12430564,"delete_count":0,"lbm_write_time_us":21900,"lbm_writes_lt_1ms":306,"reinsert_count":0,"update_count":1515}
I20260812 06:19:10.612809 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:10.626796 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5151,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:10.627588 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:10.776459 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.149s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":12501,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28535,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.777275 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:10.846655 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.069s	user 0.009s	sys 0.040s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17480,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.847565 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:10.864176 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.016s	user 0.001s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.865051 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushMRSOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:10.916462 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushMRSOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.051s	user 0.025s	sys 0.013s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":222,"dirs.run_cpu_time_us":443,"dirs.run_wall_time_us":2894,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2480,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:10.917359 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling LogGCOp(614114f7388b41e3ba5338603f0569da): free 121006442 bytes of WAL
I20260812 06:19:10.917677 17918 log_reader.cc:385] T 614114f7388b41e3ba5338603f0569da: removed 12 log segments from log reader
I20260812 06:19:10.917729 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000003 (ops 11-15)
I20260812 06:19:10.917764 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000004 (ops 16-20)
I20260812 06:19:10.917838 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000005 (ops 21-25)
I20260812 06:19:10.917894 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000006 (ops 26-30)
I20260812 06:19:10.917949 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000007 (ops 31-34)
I20260812 06:19:10.918399 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000008 (ops 35-39)
I20260812 06:19:10.918473 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000009 (ops 40-44)
I20260812 06:19:10.918496 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000010 (ops 45-49)
I20260812 06:19:10.918814 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000011 (ops 50-54)
I20260812 06:19:10.918953 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000012 (ops 55-59)
I20260812 06:19:10.918982 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000013 (ops 60-64)
I20260812 06:19:10.919029 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000014 (ops 65-69)
I20260812 06:19:10.955191 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: LogGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.038s	user 0.002s	sys 0.035s Metrics: {}
I20260812 06:19:10.956200 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da): 483 bytes on disk
I20260812 06:19:10.956887 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.957479 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=3.181125
I20260812 06:19:10.975256 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5644,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:10.976025 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:10.988267 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.989264 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:11.255419 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.266s	user 0.178s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":853,"lbm_read_time_us":19213,"lbm_reads_lt_1ms":674,"lbm_write_time_us":46478,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":221,"threads_started":1,"update_count":3000}
I20260812 06:19:11.256443 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=11.118625
I20260812 06:19:11.325563 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.069s	user 0.034s	sys 0.024s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":29444,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:19:11.326337 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:11.342070 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.342777 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:11.354420 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.355115 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:11.569288 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.214s	user 0.136s	sys 0.072s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1732,"lbm_read_time_us":14342,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36484,"lbm_writes_lt_1ms":543,"mutex_wait_us":526,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:11.569955 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=11.118625
I20260812 06:19:11.623700 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.054s	user 0.026s	sys 0.027s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18399,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:11.624384 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:11.638382 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.639441 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:11.820101 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.180s	user 0.103s	sys 0.076s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":759,"lbm_read_time_us":14780,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28533,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:11.820909 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:11.878701 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.057s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22179,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:11.879585 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:11.895270 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.015s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.896347 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:12.080529 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.184s	user 0.138s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":16415,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":463,"lbm_write_time_us":34971,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:19:12.081282 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:12.121169 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.040s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:19:12.121901 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:12.141115 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.019s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6497,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.141847 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:12.338515 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.196s	user 0.145s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1068,"lbm_read_time_us":13252,"lbm_reads_lt_1ms":468,"lbm_write_time_us":37581,"lbm_writes_lt_1ms":443,"mutex_wait_us":384,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:19:12.339306 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=14.095187
I20260812 06:19:12.396436 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.057s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25508,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.397364 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:12.420984 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.023s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.422215 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:12.640158 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.218s	user 0.153s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":12294,"lbm_reads_lt_1ms":572,"lbm_write_time_us":41373,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2500}
I20260812 06:19:12.641185 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=14.095187
I20260812 06:19:12.699302 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.058s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26301,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.700052 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushMRSOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:12.738416 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushMRSOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.038s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":1670,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3086,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:12.739672 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling LogGCOp(614114f7388b41e3ba5338603f0569da): free 112239265 bytes of WAL
I20260812 06:19:12.740105 17918 log_reader.cc:385] T 614114f7388b41e3ba5338603f0569da: removed 11 log segments from log reader
I20260812 06:19:12.740373 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000015 (ops 70-74)
I20260812 06:19:12.740567 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000016 (ops 75-78)
I20260812 06:19:12.740795 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000017 (ops 79-83)
I20260812 06:19:12.740826 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000018 (ops 84-88)
I20260812 06:19:12.740850 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000019 (ops 89-93)
I20260812 06:19:12.740872 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000020 (ops 94-98)
I20260812 06:19:12.740895 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000021 (ops 99-103)
I20260812 06:19:12.740975 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000022 (ops 104-108)
I20260812 06:19:12.741045 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000023 (ops 109-113)
I20260812 06:19:12.741086 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000024 (ops 114-118)
I20260812 06:19:12.741110 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000025 (ops 119-123)
I20260812 06:19:12.775025 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: LogGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.035s	user 0.007s	sys 0.024s Metrics: {}
I20260812 06:19:12.775733 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=4.173312
I20260812 06:19:12.799881 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":6194894,"delete_count":0,"lbm_write_time_us":9934,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:19:12.800750 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling LogGCOp(614114f7388b41e3ba5338603f0569da): free 8767174 bytes of WAL
I20260812 06:19:12.801362 17918 log_reader.cc:385] T 614114f7388b41e3ba5338603f0569da: removed 1 log segments from log reader
I20260812 06:19:12.801517 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000026 (ops 124-128)
I20260812 06:19:12.804759 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: LogGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:12.805524 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da): 462 bytes on disk
I20260812 06:19:12.806470 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":133,"lbm_reads_lt_1ms":4}
I20260812 06:19:12.807379 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:12.818647 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":3724,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:19:12.819690 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:13.124864 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.305s	user 0.211s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":259,"lbm_read_time_us":18948,"lbm_reads_lt_1ms":673,"lbm_write_time_us":53690,"lbm_writes_lt_1ms":643,"mutex_wait_us":85,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:19:13.127404 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=18.063937
I20260812 06:19:13.207729 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.080s	user 0.055s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":37226,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:13.208701 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:13.232975 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.024s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.233601 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:13.457940 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.224s	user 0.139s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1075,"lbm_read_time_us":16868,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38946,"lbm_writes_lt_1ms":643,"mutex_wait_us":497,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":3000}
I20260812 06:19:13.458653 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=14.095187
I20260812 06:19:13.547837 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.089s	user 0.045s	sys 0.029s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":32271,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.548625 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=6.157687
I20260812 06:19:13.595203 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.046s	user 0.026s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13826,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:13.595937 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:13.611936 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.612954 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:13.847695 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.234s	user 0.201s	sys 0.032s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938673,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2168,"lbm_read_time_us":21824,"lbm_reads_lt_1ms":773,"lbm_write_time_us":43198,"lbm_writes_lt_1ms":743,"mutex_wait_us":839,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":3500}
I20260812 06:19:13.848631 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=14.095187
I20260812 06:19:13.900151 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.051s	user 0.046s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22033,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.901314 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:13.918784 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.919386 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:14.101536 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.182s	user 0.132s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1438,"lbm_read_time_us":11758,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34293,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:19:14.102437 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:14.150208 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.048s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18123,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.150949 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:14.286906 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.136s	user 0.095s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1209,"lbm_read_time_us":8480,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20545,"lbm_writes_lt_1ms":343,"mutex_wait_us":318,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:19:14.287756 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=7.149875
I20260812 06:19:14.321358 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.033s	user 0.009s	sys 0.022s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14672,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:14.322484 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:14.339203 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.016s	user 0.013s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6455,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.339941 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:14.490955 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.151s	user 0.139s	sys 0.011s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1025,"lbm_read_time_us":11045,"lbm_reads_lt_1ms":372,"lbm_write_time_us":27654,"lbm_writes_lt_1ms":343,"mutex_wait_us":356,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":108416,"update_count":1500}
I20260812 06:19:14.491878 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=10.126437
I20260812 06:19:14.549371 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.057s	user 0.014s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21896,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.550153 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:14.565459 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.566191 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushMRSOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:14.598963 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushMRSOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":199,"dirs.run_cpu_time_us":443,"dirs.run_wall_time_us":2014,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":43264}
I20260812 06:19:14.599793 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling LogGCOp(614114f7388b41e3ba5338603f0569da): free 124257457 bytes of WAL
I20260812 06:19:14.600085 17918 log_reader.cc:385] T 614114f7388b41e3ba5338603f0569da: removed 12 log segments from log reader
I20260812 06:19:14.600140 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000027 (ops 129-132)
I20260812 06:19:14.600175 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000028 (ops 133-137)
I20260812 06:19:14.600229 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000029 (ops 138-142)
I20260812 06:19:14.600283 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000030 (ops 143-147)
I20260812 06:19:14.600317 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000031 (ops 148-152)
I20260812 06:19:14.600402 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000032 (ops 153-157)
I20260812 06:19:14.600425 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000033 (ops 158-162)
I20260812 06:19:14.600492 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000034 (ops 163-167)
I20260812 06:19:14.600554 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000035 (ops 168-172)
I20260812 06:19:14.600607 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000036 (ops 173-177)
I20260812 06:19:14.600653 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000037 (ops 178-182)
I20260812 06:19:14.600699 17918 log.cc:1079] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: Deleting log segment in path: /tmp/dist-test-task1KA6lA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541292973-17427-0/minicluster-data/ts-0-root/wals/614114f7388b41e3ba5338603f0569da/wal-000000038 (ops 183-187)
I20260812 06:19:14.634884 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: LogGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:14.635447 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=3.181125
I20260812 06:19:14.663619 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.028s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":8252,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:14.664318 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:14.679006 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.679992 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da): 463 bytes on disk
I20260812 06:19:14.680909 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: UndoDeltaBlockGCOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":173,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.682001 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:14.907210 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.225s	user 0.164s	sys 0.058s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1386,"lbm_read_time_us":13994,"lbm_reads_lt_1ms":674,"lbm_write_time_us":46939,"lbm_writes_lt_1ms":643,"mutex_wait_us":1406,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":45696,"thread_start_us":145,"threads_started":1,"update_count":3000}
I20260812 06:19:14.908174 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=14.095187
I20260812 06:19:14.986589 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.078s	user 0.030s	sys 0.043s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":37194,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.987366 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:15.012216 17427 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.196s	user 2.328s	sys 0.145s
I20260812 06:19:15.014550 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.027s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.015259 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da): perf score=2.188937
I20260812 06:19:15.027745 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: FlushDeltaMemStoresOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":500}
I20260812 06:19:15.028436 18015 maintenance_manager.cc:419] P 198383cc91f341bd894d22cc0c156ae1: Scheduling MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da): perf score=1.000000
I20260812 06:19:15.090070 17427 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.001s	sys 0.000s
I20260812 06:19:15.091048 17427 tablet_server.cc:179] TabletServer@127.17.4.193:0 shutting down...
I20260812 06:19:15.198999 17918 maintenance_manager.cc:643] P 198383cc91f341bd894d22cc0c156ae1: MajorDeltaCompactionOp(614114f7388b41e3ba5338603f0569da) complete. Timing: real 0.170s	user 0.139s	sys 0.030s Metrics: {"cfile_cache_hit":402,"cfile_cache_hit_bytes":16411201,"cfile_cache_miss":231,"cfile_cache_miss_bytes":12425056,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":992,"lbm_read_time_us":7254,"lbm_reads_lt_1ms":263,"lbm_write_time_us":35098,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":199168,"update_count":3000}
I20260812 06:19:15.199941 17427 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:15.200351 17427 tablet_replica.cc:333] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1: stopping tablet replica
I20260812 06:19:15.200573 17427 raft_consensus.cc:2243] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.200865 17427 raft_consensus.cc:2272] T 614114f7388b41e3ba5338603f0569da P 198383cc91f341bd894d22cc0c156ae1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.219094 17427 tablet_server.cc:196] TabletServer@127.17.4.193:0 shutdown complete.
I20260812 06:19:15.255219 17427 master.cc:562] Master@127.17.4.254:39833 shutting down...
I20260812 06:19:15.260316 17427 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:15.260720 17427 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:15.260833 17427 tablet_replica.cc:333] T 00000000000000000000000000000000 P ecab92acf0274b60a68967bcde57a890: stopping tablet replica
I20260812 06:19:15.275015 17427 master.cc:584] Master@127.17.4.254:39833 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6868 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (14078 ms total)

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