[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:36.423619 19592 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.34.62:34363
I20260812 06:18:36.424566 19592 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:36.425153 19592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:36.431154 19599 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.431260 19592 server_base.cc:1061] running on GCE node
W20260812 06:18:36.431284 19602 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.431476 19600 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.431901 19592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:36.432046 19592 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:36.432077 19592 hybrid_clock.cc:648] HybridClock initialized: now 1786515516432076 us; error 0 us; skew 500 ppm
I20260812 06:18:36.433671 19592 webserver.cc:533] Webserver started at http://127.19.34.62:42429/ using document root <none> and password file <none>
I20260812 06:18:36.434126 19592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:36.434181 19592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:36.434357 19592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:36.435998 19592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/master-0-root/instance:
uuid: "9101f56046aa45cca4528cf9f762e4d4"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-92m1"
I20260812 06:18:36.439091 19592 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:36.441004 19612 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.441931 19592 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:36.442070 19592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/master-0-root
uuid: "9101f56046aa45cca4528cf9f762e4d4"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-92m1"
I20260812 06:18:36.442162 19592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.480747 19592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.481436 19592 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:36.481618 19592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.489059 19592 rpc_server.cc:307] RPC server started. Bound to: 127.19.34.62:34363
I20260812 06:18:36.489073 19701 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.34.62:34363 every 8 connection(s)
I20260812 06:18:36.491269 19702 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.496551 19702 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4: Bootstrap starting.
I20260812 06:18:36.499028 19702 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.500065 19702 log.cc:826] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:36.501804 19702 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4: No bootstrap required, opened a new log
I20260812 06:18:36.504563 19702 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9101f56046aa45cca4528cf9f762e4d4" member_type: VOTER }
I20260812 06:18:36.504721 19702 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.504812 19702 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9101f56046aa45cca4528cf9f762e4d4, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.505396 19702 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [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: "9101f56046aa45cca4528cf9f762e4d4" member_type: VOTER }
I20260812 06:18:36.505561 19702 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.505630 19702 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.505795 19702 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.506583 19702 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9101f56046aa45cca4528cf9f762e4d4" member_type: VOTER }
I20260812 06:18:36.507005 19702 leader_election.cc:304] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [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: 9101f56046aa45cca4528cf9f762e4d4; no voters: 
I20260812 06:18:36.507354 19702 leader_election.cc:290] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.507505 19707 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.507745 19707 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 1 LEADER]: Becoming Leader. State: Replica: 9101f56046aa45cca4528cf9f762e4d4, State: Running, Role: LEADER
I20260812 06:18:36.508168 19707 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [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: "9101f56046aa45cca4528cf9f762e4d4" member_type: VOTER }
I20260812 06:18:36.508329 19702 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:36.510040 19712 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9101f56046aa45cca4528cf9f762e4d4. Latest consensus state: current_term: 1 leader_uuid: "9101f56046aa45cca4528cf9f762e4d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9101f56046aa45cca4528cf9f762e4d4" member_type: VOTER } }
I20260812 06:18:36.510049 19709 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9101f56046aa45cca4528cf9f762e4d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9101f56046aa45cca4528cf9f762e4d4" member_type: VOTER } }
I20260812 06:18:36.510169 19712 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:36.510169 19709 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:36.510587 19729 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:36.510685 19592 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:36.513087 19729 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:36.517772 19729 catalog_manager.cc:1383] Generated new cluster ID: c51fb33ff7564b2abe2b91fc2d83dbf0
I20260812 06:18:36.517841 19729 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:36.538635 19729 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:36.539575 19729 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:36.551425 19729 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4: Generated new TSK 0
I20260812 06:18:36.552083 19729 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:36.575544 19592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:36.578397 19741 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.578359 19738 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.578457 19739 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.578687 19592 server_base.cc:1061] running on GCE node
I20260812 06:18:36.578953 19592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:36.578996 19592 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:36.579012 19592 hybrid_clock.cc:648] HybridClock initialized: now 1786515516579012 us; error 0 us; skew 500 ppm
I20260812 06:18:36.580008 19592 webserver.cc:533] Webserver started at http://127.19.34.1:39453/ using document root <none> and password file <none>
I20260812 06:18:36.580180 19592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:36.580227 19592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:36.580322 19592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:36.580739 19592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/instance:
uuid: "c07e3b6f23af43a3b2884bd1ccddf6d9"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-92m1"
I20260812 06:18:36.582276 19592 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:36.583276 19746 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.583534 19592 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:36.583600 19592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root
uuid: "c07e3b6f23af43a3b2884bd1ccddf6d9"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-92m1"
I20260812 06:18:36.583684 19592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.596314 19592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.596755 19592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.597266 19592 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:36.598384 19592 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:36.598438 19592 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.598506 19592 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:36.598541 19592 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.605320 19592 rpc_server.cc:307] RPC server started. Bound to: 127.19.34.1:44159
I20260812 06:18:36.605358 19851 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.34.1:44159 every 8 connection(s)
I20260812 06:18:36.641551 19853 heartbeater.cc:344] Connected to a master server at 127.19.34.62:34363
I20260812 06:18:36.641806 19853 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:36.642274 19853 heartbeater.cc:507] Master 127.19.34.62:34363 requested a full tablet report, sending...
I20260812 06:18:36.643862 19639 ts_manager.cc:194] Registered new tserver with Master: c07e3b6f23af43a3b2884bd1ccddf6d9 (127.19.34.1:44159)
I20260812 06:18:36.644397 19592 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.038455242s
I20260812 06:18:36.645435 19639 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53832
I20260812 06:18:36.654443 19639 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53844:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:36.669442 19794 tablet_service.cc:1511] Processing CreateTablet for tablet a35a38e6adf84844bae77fc057b6cb55 (DEFAULT_TABLE table=heavy-update-compaction-test [id=9b989ae4608048e2a2597bf57b3ce1c4]), partition=
I20260812 06:18:36.669922 19794 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a35a38e6adf84844bae77fc057b6cb55. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.672827 19875 tablet_bootstrap.cc:492] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Bootstrap starting.
I20260812 06:18:36.674018 19875 tablet_bootstrap.cc:654] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.675168 19875 tablet_bootstrap.cc:492] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: No bootstrap required, opened a new log
I20260812 06:18:36.675330 19875 ts_tablet_manager.cc:1403] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:18:36.675765 19875 raft_consensus.cc:359] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c07e3b6f23af43a3b2884bd1ccddf6d9" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 44159 } }
I20260812 06:18:36.675901 19875 raft_consensus.cc:385] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.675973 19875 raft_consensus.cc:740] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c07e3b6f23af43a3b2884bd1ccddf6d9, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.676151 19875 consensus_queue.cc:260] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [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: "c07e3b6f23af43a3b2884bd1ccddf6d9" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 44159 } }
I20260812 06:18:36.676258 19875 raft_consensus.cc:399] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.676317 19875 raft_consensus.cc:493] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.676394 19875 raft_consensus.cc:3060] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.677284 19875 raft_consensus.cc:515] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c07e3b6f23af43a3b2884bd1ccddf6d9" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 44159 } }
I20260812 06:18:36.677471 19875 leader_election.cc:304] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [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: c07e3b6f23af43a3b2884bd1ccddf6d9; no voters: 
I20260812 06:18:36.677762 19875 leader_election.cc:290] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.678076 19883 raft_consensus.cc:2804] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.678194 19875 ts_tablet_manager.cc:1434] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:36.678329 19883 raft_consensus.cc:697] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 1 LEADER]: Becoming Leader. State: Replica: c07e3b6f23af43a3b2884bd1ccddf6d9, State: Running, Role: LEADER
I20260812 06:18:36.678488 19883 consensus_queue.cc:237] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [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: "c07e3b6f23af43a3b2884bd1ccddf6d9" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 44159 } }
I20260812 06:18:36.678632 19853 heartbeater.cc:499] Master 127.19.34.62:34363 was elected leader, sending a full tablet report...
I20260812 06:18:36.681318 19639 catalog_manager.cc:5719] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 reported cstate change: term changed from 0 to 1, leader changed from <none> to c07e3b6f23af43a3b2884bd1ccddf6d9 (127.19.34.1). New cstate: current_term: 1 leader_uuid: "c07e3b6f23af43a3b2884bd1ccddf6d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c07e3b6f23af43a3b2884bd1ccddf6d9" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 44159 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:36.743327 19592 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.020s	sys 0.004s
I20260812 06:18:36.856604 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55): perf score=15.086190
I20260812 06:18:36.993952 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.137s	user 0.090s	sys 0.044s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":495,"delete_count":0,"dirs.queue_time_us":29,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":656,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":31807,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":167,"threads_started":1,"update_count":1050}
I20260812 06:18:36.995010 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling LogGCOp(a35a38e6adf84844bae77fc057b6cb55): free 8725963 bytes of WAL
I20260812 06:18:36.995353 19756 log_reader.cc:385] T a35a38e6adf84844bae77fc057b6cb55: removed 1 log segments from log reader
I20260812 06:18:36.995416 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000001 (ops 1-6)
I20260812 06:18:36.997678 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: LogGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:36.998008 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:37.015846 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6579,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.016350 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:37.147348 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.131s	user 0.093s	sys 0.030s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":818,"lbm_read_time_us":7848,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23787,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":366,"threads_started":5,"update_count":1500}
I20260812 06:18:37.148016 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=10.126437
I20260812 06:18:37.191385 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.043s	user 0.013s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15896,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.191810 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55): 12308958 bytes on disk
I20260812 06:18:37.192281 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.192715 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:37.204298 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.205014 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:37.333496 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":9379,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24186,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:18:37.334159 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=10.126437
I20260812 06:18:37.398116 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.064s	user 0.038s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18124,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.398741 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:37.411016 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.411448 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:37.563378 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.152s	user 0.088s	sys 0.062s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":10253,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25229,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:18:37.564225 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=7.149875
I20260812 06:18:37.589311 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.025s	user 0.014s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10502,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:37.589794 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:37.605350 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5916,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.605844 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:37.719095 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.113s	user 0.088s	sys 0.017s 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":966,"lbm_read_time_us":5849,"lbm_reads_lt_1ms":372,"lbm_write_time_us":18551,"lbm_writes_lt_1ms":343,"mutex_wait_us":286,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":1500}
I20260812 06:18:37.719652 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=10.126437
I20260812 06:18:37.765784 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.046s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.766286 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:37.778136 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.778734 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:37.907462 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.129s	user 0.100s	sys 0.028s 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":164,"lbm_read_time_us":8792,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24937,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:18:37.908212 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=10.126437
I20260812 06:18:37.948356 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.040s	user 0.007s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13130,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.949075 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:37.961673 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.962110 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:38.117647 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.155s	user 0.097s	sys 0.051s 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":554,"lbm_read_time_us":10496,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25557,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:38.118300 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=10.126437
I20260812 06:18:38.163298 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.045s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14128,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.163733 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:38.174185 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4049,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.175019 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:38.309876 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.135s	user 0.111s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1283,"lbm_read_time_us":10338,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25450,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:38.310705 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=10.126437
I20260812 06:18:38.352021 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.041s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15092,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.352597 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:38.367591 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.368124 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:38.398980 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1167,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1772,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:38.399781 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling LogGCOp(a35a38e6adf84844bae77fc057b6cb55): free 132571242 bytes of WAL
I20260812 06:18:38.400012 19756 log_reader.cc:385] T a35a38e6adf84844bae77fc057b6cb55: removed 13 log segments from log reader
I20260812 06:18:38.400055 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000002 (ops 7-11)
I20260812 06:18:38.400104 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000003 (ops 12-16)
I20260812 06:18:38.400151 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000004 (ops 17-21)
I20260812 06:18:38.400190 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000005 (ops 22-26)
I20260812 06:18:38.400230 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000006 (ops 27-31)
I20260812 06:18:38.400285 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000007 (ops 32-36)
I20260812 06:18:38.400319 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000008 (ops 37-40)
I20260812 06:18:38.400358 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000009 (ops 41-45)
I20260812 06:18:38.400398 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000010 (ops 46-50)
I20260812 06:18:38.400449 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000011 (ops 51-55)
I20260812 06:18:38.400489 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000012 (ops 56-60)
I20260812 06:18:38.400530 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000013 (ops 61-64)
I20260812 06:18:38.400569 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000014 (ops 65-69)
I20260812 06:18:38.430210 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: LogGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:38.430675 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=3.181125
I20260812 06:18:38.447901 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5087238,"delete_count":0,"lbm_write_time_us":7169,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:18:38.448287 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55): 472 bytes on disk
I20260812 06:18:38.448652 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.449059 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.196750
I20260812 06:18:38.458408 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.009s	user 0.006s	sys 0.000s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":2942,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:38.458921 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:38.631834 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.173s	user 0.138s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":469,"lbm_read_time_us":12242,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35248,"lbm_writes_lt_1ms":643,"mutex_wait_us":72,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:38.634093 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:38.688046 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.054s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24603,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.688540 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:38.701252 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4679,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.702033 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:38.857055 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.155s	user 0.112s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":302,"lbm_read_time_us":9281,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29775,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:18:38.857693 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:38.908337 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22331,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.908840 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:39.057227 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.148s	user 0.118s	sys 0.024s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":262,"lbm_read_time_us":9477,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22929,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.057946 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:39.110435 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.052s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23302,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.110954 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:39.127879 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.128337 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:39.309384 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.181s	user 0.109s	sys 0.059s 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":345,"lbm_read_time_us":10838,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29186,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:18:39.310053 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:39.360034 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.050s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20700,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.360677 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:39.373355 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.374027 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:39.531957 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.158s	user 0.108s	sys 0.047s 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":135,"lbm_read_time_us":12986,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30461,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":67968,"update_count":2500}
I20260812 06:18:39.532719 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=11.118625
I20260812 06:18:39.573511 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.041s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17492,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1550}
I20260812 06:18:39.574108 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:39.592087 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6506,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.592717 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:39.713826 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.121s	user 0.106s	sys 0.015s 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":1410,"lbm_read_time_us":7271,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23075,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.714671 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=11.118625
I20260812 06:18:39.754022 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.039s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17444,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:39.754531 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:39.766580 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4662,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.767088 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:39.798723 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1206,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1468,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:39.799798 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling LogGCOp(a35a38e6adf84844bae77fc057b6cb55): free 115943241 bytes of WAL
I20260812 06:18:39.800081 19756 log_reader.cc:385] T a35a38e6adf84844bae77fc057b6cb55: removed 11 log segments from log reader
I20260812 06:18:39.800136 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000015 (ops 70-74)
I20260812 06:18:39.800165 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000016 (ops 75-79)
I20260812 06:18:39.800184 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000017 (ops 80-84)
I20260812 06:18:39.800243 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000018 (ops 85-89)
I20260812 06:18:39.800288 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000019 (ops 90-94)
I20260812 06:18:39.800307 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000020 (ops 95-99)
I20260812 06:18:39.800323 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000021 (ops 100-104)
I20260812 06:18:39.800380 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000022 (ops 105-109)
I20260812 06:18:39.800438 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000023 (ops 110-114)
I20260812 06:18:39.800467 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000024 (ops 115-119)
I20260812 06:18:39.800503 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000025 (ops 120-124)
I20260812 06:18:39.826411 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: LogGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:39.827057 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55): 472 bytes on disk
I20260812 06:18:39.827648 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.828318 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=4.173312
I20260812 06:18:39.845191 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":5497489,"delete_count":0,"lbm_write_time_us":7041,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:18:39.845716 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling LogGCOp(a35a38e6adf84844bae77fc057b6cb55): free 8767120 bytes of WAL
I20260812 06:18:39.845983 19756 log_reader.cc:385] T a35a38e6adf84844bae77fc057b6cb55: removed 1 log segments from log reader
I20260812 06:18:39.846045 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000026 (ops 125-129)
I20260812 06:18:39.848182 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: LogGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:39.848486 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.196750
I20260812 06:18:39.861104 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:39.861714 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:40.038921 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.177s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836334,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":511,"lbm_read_time_us":13137,"lbm_reads_lt_1ms":666,"lbm_write_time_us":38637,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29056,"thread_start_us":118,"threads_started":1,"update_count":3000}
I20260812 06:18:40.039757 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:40.085507 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.046s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.086110 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:40.101960 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.102778 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:40.266861 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.164s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":11628,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31869,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:40.267714 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:40.334188 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.066s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24086,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.334764 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:40.346192 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.346928 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:40.517554 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.170s	user 0.131s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":11715,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31357,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":70272,"update_count":2500}
I20260812 06:18:40.518119 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:40.572937 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.055s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":17781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.573457 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:40.584132 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.584584 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:40.756445 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.172s	user 0.110s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":13293,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27701,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:18:40.757318 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:40.833070 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.076s	user 0.019s	sys 0.055s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27574,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.833779 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:40.853456 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.854135 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:41.034727 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.180s	user 0.104s	sys 0.076s 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":1107,"lbm_read_time_us":12189,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30562,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:18:41.035413 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:41.094602 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.059s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20854,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.095170 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:41.106143 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.106621 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:41.278410 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.172s	user 0.091s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1475,"lbm_read_time_us":12041,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28288,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:41.279016 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=11.118625
I20260812 06:18:41.314613 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.035s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15389,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:41.315377 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:41.330569 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5538,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.331132 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:41.381270 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushMRSOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.050s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":1130,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1544,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1792}
I20260812 06:18:41.382507 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=6.157687
I20260812 06:18:41.406713 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.024s	user 0.018s	sys 0.003s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":10178,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:41.407600 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling LogGCOp(a35a38e6adf84844bae77fc057b6cb55): free 120553645 bytes of WAL
I20260812 06:18:41.407863 19756 log_reader.cc:385] T a35a38e6adf84844bae77fc057b6cb55: removed 12 log segments from log reader
I20260812 06:18:41.407927 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000027 (ops 130-134)
I20260812 06:18:41.408013 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000028 (ops 135-139)
I20260812 06:18:41.408058 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000029 (ops 140-144)
I20260812 06:18:41.408104 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000030 (ops 145-148)
I20260812 06:18:41.408146 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000031 (ops 149-153)
I20260812 06:18:41.408190 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000032 (ops 154-158)
I20260812 06:18:41.408233 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000033 (ops 159-163)
I20260812 06:18:41.408277 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000034 (ops 164-168)
I20260812 06:18:41.408320 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000035 (ops 169-172)
I20260812 06:18:41.408399 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000036 (ops 173-177)
I20260812 06:18:41.408453 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000037 (ops 178-182)
I20260812 06:18:41.408499 19756 log.cc:1079] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/a35a38e6adf84844bae77fc057b6cb55/wal-000000038 (ops 183-187)
I20260812 06:18:41.432186 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: LogGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:41.432717 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=2.188937
I20260812 06:18:41.448438 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.449059 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:41.663869 19592 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.920s	user 1.812s	sys 0.155s
I20260812 06:18:41.689458 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.240s	user 0.159s	sys 0.078s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938779,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17278,"lbm_reads_lt_1ms":766,"lbm_write_time_us":43441,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:18:41.689960 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55): 482 bytes on disk
I20260812 06:18:41.690371 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: UndoDeltaBlockGCOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.690908 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55): perf score=14.095187
I20260812 06:18:41.725235 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: FlushDeltaMemStoresOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.034s	user 0.018s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16770,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:41.725744 19854 maintenance_manager.cc:419] P c07e3b6f23af43a3b2884bd1ccddf6d9: Scheduling MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55): perf score=1.000000
I20260812 06:18:41.786237 19592 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.122s	user 0.005s	sys 0.000s
I20260812 06:18:41.787003 19592 tablet_server.cc:179] TabletServer@127.19.34.1:0 shutting down...
I20260812 06:18:41.849860 19756 maintenance_manager.cc:643] P c07e3b6f23af43a3b2884bd1ccddf6d9: MajorDeltaCompactionOp(a35a38e6adf84844bae77fc057b6cb55) complete. Timing: real 0.124s	user 0.084s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":768,"lbm_read_time_us":9524,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23179,"lbm_writes_lt_1ms":443,"mutex_wait_us":113,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:41.850672 19592 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:41.851114 19592 tablet_replica.cc:333] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9: stopping tablet replica
I20260812 06:18:41.851385 19592 raft_consensus.cc:2243] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:41.851627 19592 raft_consensus.cc:2272] T a35a38e6adf84844bae77fc057b6cb55 P c07e3b6f23af43a3b2884bd1ccddf6d9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:41.866997 19592 tablet_server.cc:196] TabletServer@127.19.34.1:0 shutdown complete.
I20260812 06:18:41.903790 19592 master.cc:562] Master@127.19.34.62:34363 shutting down...
I20260812 06:18:41.908224 19592 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:41.908429 19592 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:41.908524 19592 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9101f56046aa45cca4528cf9f762e4d4: stopping tablet replica
I20260812 06:18:41.921141 19592 master.cc:584] Master@127.19.34.62:34363 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5595 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:42.033919 19592 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.34.62:37407
I20260812 06:18:42.034425 19592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:42.037168 19592 server_base.cc:1061] running on GCE node
W20260812 06:18:42.037264 19913 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.037276 19911 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.037180 19910 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.037832 19592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.037884 19592 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.037904 19592 hybrid_clock.cc:648] HybridClock initialized: now 1786515522037904 us; error 0 us; skew 500 ppm
I20260812 06:18:42.038800 19592 webserver.cc:533] Webserver started at http://127.19.34.62:36149/ using document root <none> and password file <none>
I20260812 06:18:42.038964 19592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.039036 19592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.039103 19592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.039606 19592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/master-0-root/instance:
uuid: "684acee5756a4dc8bdd877851f076b53"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-92m1"
I20260812 06:18:42.041384 19592 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:42.042497 19921 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.042752 19592 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:42.042968 19592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/master-0-root
uuid: "684acee5756a4dc8bdd877851f076b53"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-92m1"
I20260812 06:18:42.043079 19592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.055739 19592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.056162 19592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.060783 19592 rpc_server.cc:307] RPC server started. Bound to: 127.19.34.62:37407
I20260812 06:18:42.060847 20011 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.34.62:37407 every 8 connection(s)
I20260812 06:18:42.061893 20012 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.064179 20012 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53: Bootstrap starting.
I20260812 06:18:42.064981 20012 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.066030 20012 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53: No bootstrap required, opened a new log
I20260812 06:18:42.066447 20012 raft_consensus.cc:359] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "684acee5756a4dc8bdd877851f076b53" member_type: VOTER }
I20260812 06:18:42.066558 20012 raft_consensus.cc:385] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.066627 20012 raft_consensus.cc:740] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 684acee5756a4dc8bdd877851f076b53, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.066800 20012 consensus_queue.cc:260] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [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: "684acee5756a4dc8bdd877851f076b53" member_type: VOTER }
I20260812 06:18:42.066902 20012 raft_consensus.cc:399] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.066960 20012 raft_consensus.cc:493] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.067027 20012 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.067792 20012 raft_consensus.cc:515] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "684acee5756a4dc8bdd877851f076b53" member_type: VOTER }
I20260812 06:18:42.067951 20012 leader_election.cc:304] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [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: 684acee5756a4dc8bdd877851f076b53; no voters: 
I20260812 06:18:42.068159 20012 leader_election.cc:290] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.068267 20017 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.068472 20017 raft_consensus.cc:697] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 1 LEADER]: Becoming Leader. State: Replica: 684acee5756a4dc8bdd877851f076b53, State: Running, Role: LEADER
I20260812 06:18:42.068624 20017 consensus_queue.cc:237] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [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: "684acee5756a4dc8bdd877851f076b53" member_type: VOTER }
I20260812 06:18:42.068677 20012 sys_catalog.cc:565] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:42.069092 20020 sys_catalog.cc:455] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "684acee5756a4dc8bdd877851f076b53" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "684acee5756a4dc8bdd877851f076b53" member_type: VOTER } }
I20260812 06:18:42.069135 20021 sys_catalog.cc:455] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 684acee5756a4dc8bdd877851f076b53. Latest consensus state: current_term: 1 leader_uuid: "684acee5756a4dc8bdd877851f076b53" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "684acee5756a4dc8bdd877851f076b53" member_type: VOTER } }
I20260812 06:18:42.069258 20020 sys_catalog.cc:458] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.069337 20021 sys_catalog.cc:458] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.069810 20024 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:42.070914 20024 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:42.071125 19592 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:42.072829 20024 catalog_manager.cc:1383] Generated new cluster ID: 5c3bfe6f55f245aebb3ad46ed06c1261
I20260812 06:18:42.072885 20024 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:42.079535 20024 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:42.080113 20024 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:42.091246 20024 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53: Generated new TSK 0
I20260812 06:18:42.091432 20024 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:42.103742 19592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:42.105782 20046 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.105763 20051 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.105798 19592 server_base.cc:1061] running on GCE node
W20260812 06:18:42.105883 20047 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.106243 19592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.106287 19592 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.106302 19592 hybrid_clock.cc:648] HybridClock initialized: now 1786515522106302 us; error 0 us; skew 500 ppm
I20260812 06:18:42.107182 19592 webserver.cc:533] Webserver started at http://127.19.34.1:42561/ using document root <none> and password file <none>
I20260812 06:18:42.107398 19592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.107470 19592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.107553 19592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.107986 19592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/instance:
uuid: "8baf0a9e7184412297bb44eb59d8e300"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-92m1"
I20260812 06:18:42.109491 19592 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:42.110514 20058 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.110770 19592 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:42.110839 19592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root
uuid: "8baf0a9e7184412297bb44eb59d8e300"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-92m1"
I20260812 06:18:42.110934 19592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.153894 19592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.154362 19592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.154747 19592 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:42.155356 19592 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:42.155400 19592 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.155462 19592 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:42.155514 19592 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.160138 19592 rpc_server.cc:307] RPC server started. Bound to: 127.19.34.1:36639
I20260812 06:18:42.160173 20162 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.34.1:36639 every 8 connection(s)
I20260812 06:18:42.169898 20163 heartbeater.cc:344] Connected to a master server at 127.19.34.62:37407
I20260812 06:18:42.170017 20163 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:42.170215 20163 heartbeater.cc:507] Master 127.19.34.62:37407 requested a full tablet report, sending...
I20260812 06:18:42.170903 19948 ts_manager.cc:194] Registered new tserver with Master: 8baf0a9e7184412297bb44eb59d8e300 (127.19.34.1:36639)
I20260812 06:18:42.171626 19592 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011004103s
I20260812 06:18:42.171803 19948 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59492
I20260812 06:18:42.179129 19948 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59496:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:42.187624 20102 tablet_service.cc:1511] Processing CreateTablet for tablet c9cb9c317e1d4a3fa594ab87d497f207 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5e30ddd6c6de45f78ed063a23974f961]), partition=
I20260812 06:18:42.187943 20102 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c9cb9c317e1d4a3fa594ab87d497f207. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.189993 20185 tablet_bootstrap.cc:492] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Bootstrap starting.
I20260812 06:18:42.190940 20185 tablet_bootstrap.cc:654] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.192124 20185 tablet_bootstrap.cc:492] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: No bootstrap required, opened a new log
I20260812 06:18:42.192239 20185 ts_tablet_manager.cc:1403] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:42.192698 20185 raft_consensus.cc:359] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8baf0a9e7184412297bb44eb59d8e300" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 36639 } }
I20260812 06:18:42.192816 20185 raft_consensus.cc:385] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.192862 20185 raft_consensus.cc:740] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8baf0a9e7184412297bb44eb59d8e300, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.193030 20185 consensus_queue.cc:260] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [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: "8baf0a9e7184412297bb44eb59d8e300" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 36639 } }
I20260812 06:18:42.193138 20185 raft_consensus.cc:399] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.193188 20185 raft_consensus.cc:493] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.193248 20185 raft_consensus.cc:3060] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.194126 20185 raft_consensus.cc:515] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8baf0a9e7184412297bb44eb59d8e300" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 36639 } }
I20260812 06:18:42.194288 20185 leader_election.cc:304] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [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: 8baf0a9e7184412297bb44eb59d8e300; no voters: 
I20260812 06:18:42.194526 20185 leader_election.cc:290] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.194658 20187 raft_consensus.cc:2804] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.194918 20185 ts_tablet_manager.cc:1434] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:42.194965 20163 heartbeater.cc:499] Master 127.19.34.62:37407 was elected leader, sending a full tablet report...
I20260812 06:18:42.194919 20187 raft_consensus.cc:697] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 1 LEADER]: Becoming Leader. State: Replica: 8baf0a9e7184412297bb44eb59d8e300, State: Running, Role: LEADER
I20260812 06:18:42.195165 20187 consensus_queue.cc:237] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [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: "8baf0a9e7184412297bb44eb59d8e300" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 36639 } }
I20260812 06:18:42.196483 19948 catalog_manager.cc:5719] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8baf0a9e7184412297bb44eb59d8e300 (127.19.34.1). New cstate: current_term: 1 leader_uuid: "8baf0a9e7184412297bb44eb59d8e300" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8baf0a9e7184412297bb44eb59d8e300" member_type: VOTER last_known_addr { host: "127.19.34.1" port: 36639 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:42.257396 19592 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.011s	sys 0.012s
I20260812 06:18:42.411082 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=19.054940
I20260812 06:18:42.556145 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.145s	user 0.120s	sys 0.024s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":856,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35705,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1450}
I20260812 06:18:42.556779 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207): free 20743831 bytes of WAL
I20260812 06:18:42.557062 20065 log_reader.cc:385] T c9cb9c317e1d4a3fa594ab87d497f207: removed 2 log segments from log reader
I20260812 06:18:42.557125 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000001 (ops 1-6)
I20260812 06:18:42.557163 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000002 (ops 7-11)
I20260812 06:18:42.563474 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:18:42.563923 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:42.600924 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.037s	user 0.004s	sys 0.020s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.601395 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207): 16821646 bytes on disk
I20260812 06:18:42.601771 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.602149 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:42.612695 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.613066 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:42.806399 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.193s	user 0.111s	sys 0.081s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405560,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1138,"lbm_read_time_us":13717,"lbm_reads_lt_1ms":559,"lbm_write_time_us":30022,"lbm_writes_lt_1ms":533,"mutex_wait_us":283,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":347,"threads_started":5,"update_count":2450}
I20260812 06:18:42.807021 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=11.118625
I20260812 06:18:42.842535 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.035s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15140,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:42.843173 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:42.860069 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.016s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5498,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.860620 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:42.993739 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.133s	user 0.094s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":657,"lbm_read_time_us":7574,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24766,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":2000}
I20260812 06:18:42.994328 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=10.126437
I20260812 06:18:43.031458 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.037s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15770,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.031955 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:43.045240 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.045814 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:43.174577 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.128s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":10189,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23348,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":77312,"update_count":2000}
I20260812 06:18:43.175414 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=10.126437
I20260812 06:18:43.215047 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.039s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16626,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.215559 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:43.225596 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.225996 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:43.352751 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.127s	user 0.088s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":9258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23872,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:43.353451 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=10.126437
I20260812 06:18:43.411778 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.058s	user 0.031s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.412367 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:43.422859 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.423260 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:43.567950 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.145s	user 0.095s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":520,"lbm_read_time_us":10227,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22509,"lbm_writes_lt_1ms":443,"mutex_wait_us":242,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:43.568572 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=10.126437
I20260812 06:18:43.608341 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.040s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15792,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.608954 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:43.621686 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.622175 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:43.751104 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.129s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":9816,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24780,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:18:43.751864 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=10.126437
I20260812 06:18:43.788184 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":14825,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.788877 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:43.801117 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.801568 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:43.829682 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":1200,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1602,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:43.830231 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207): free 120553372 bytes of WAL
I20260812 06:18:43.830446 20065 log_reader.cc:385] T c9cb9c317e1d4a3fa594ab87d497f207: removed 12 log segments from log reader
I20260812 06:18:43.830502 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000003 (ops 12-16)
I20260812 06:18:43.830554 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000004 (ops 17-21)
I20260812 06:18:43.830607 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000005 (ops 22-26)
I20260812 06:18:43.830648 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000006 (ops 27-31)
I20260812 06:18:43.830684 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000007 (ops 32-36)
I20260812 06:18:43.830720 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000008 (ops 37-41)
I20260812 06:18:43.830757 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000009 (ops 42-46)
I20260812 06:18:43.830794 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000010 (ops 47-50)
I20260812 06:18:43.830832 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000011 (ops 51-55)
I20260812 06:18:43.830868 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000012 (ops 56-60)
I20260812 06:18:43.830905 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000013 (ops 61-64)
I20260812 06:18:43.830945 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000014 (ops 65-69)
I20260812 06:18:43.857718 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:43.858166 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=3.181125
I20260812 06:18:43.875600 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6965,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.876068 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207): 447 bytes on disk
I20260812 06:18:43.876516 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.877049 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:43.886693 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3821,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.887120 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:44.065587 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.178s	user 0.144s	sys 0.034s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":675,"lbm_read_time_us":14158,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35262,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:44.066330 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:44.116845 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.050s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19048,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.117380 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:44.128183 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.128654 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:44.294320 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.165s	user 0.136s	sys 0.022s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":10349,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31917,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:18:44.295075 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:44.344344 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.049s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20296,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.345077 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:44.358232 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.358678 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:44.515908 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.157s	user 0.134s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1294,"lbm_read_time_us":10953,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31970,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30976,"update_count":2500}
I20260812 06:18:44.516669 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:44.560724 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.044s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19671,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.561148 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:44.571498 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.571885 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:44.717051 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.145s	user 0.103s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":10718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26798,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:44.718086 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=12.110812
I20260812 06:18:44.759181 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.041s	user 0.031s	sys 0.004s Metrics: {"bytes_written":13989479,"delete_count":0,"lbm_write_time_us":17086,"lbm_writes_lt_1ms":344,"reinsert_count":0,"update_count":1705}
I20260812 06:18:44.762982 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.196750
I20260812 06:18:44.781643 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.018s	user 0.008s	sys 0.002s Metrics: {"bytes_written":2830884,"delete_count":0,"lbm_write_time_us":4374,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:44.782166 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:44.791684 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3621,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.792107 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:44.969820 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.178s	user 0.111s	sys 0.063s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815763,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":354,"lbm_read_time_us":11646,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30781,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:44.970539 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:45.028769 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.058s	user 0.032s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28310,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.029310 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:45.039999 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.040436 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:45.213078 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.172s	user 0.112s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30781,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:45.213762 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:45.274947 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.061s	user 0.019s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22210,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.275609 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:45.292147 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.292722 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:45.337339 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.044s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1221,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1751,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:45.338167 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207): free 132571387 bytes of WAL
I20260812 06:18:45.338433 20065 log_reader.cc:385] T c9cb9c317e1d4a3fa594ab87d497f207: removed 13 log segments from log reader
I20260812 06:18:45.338506 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000015 (ops 70-74)
I20260812 06:18:45.338577 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000016 (ops 75-78)
I20260812 06:18:45.338631 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000017 (ops 79-83)
I20260812 06:18:45.338673 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000018 (ops 84-88)
I20260812 06:18:45.338713 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000019 (ops 89-92)
I20260812 06:18:45.338752 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000020 (ops 93-97)
I20260812 06:18:45.338791 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000021 (ops 98-102)
I20260812 06:18:45.338831 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000022 (ops 103-107)
I20260812 06:18:45.338869 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000023 (ops 108-112)
I20260812 06:18:45.338909 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000024 (ops 113-117)
I20260812 06:18:45.338948 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000025 (ops 118-122)
I20260812 06:18:45.338985 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000026 (ops 123-127)
I20260812 06:18:45.339020 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000027 (ops 128-132)
I20260812 06:18:45.366791 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.028s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:18:45.367463 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=3.181125
I20260812 06:18:45.381544 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.014s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":4601,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:18:45.381942 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:45.392076 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:45.392539 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207): 492 bytes on disk
I20260812 06:18:45.393033 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.393936 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:45.614718 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.221s	user 0.146s	sys 0.070s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":540,"lbm_read_time_us":16472,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37829,"lbm_writes_lt_1ms":743,"mutex_wait_us":264,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:45.615341 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=18.063937
I20260812 06:18:45.681906 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.066s	user 0.035s	sys 0.028s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":33285,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.682536 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:45.695791 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.696225 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:45.862262 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.166s	user 0.105s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":10993,"lbm_reads_lt_1ms":668,"lbm_write_time_us":33609,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:18:45.862967 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:45.919426 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.055s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21580,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.919917 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:45.935781 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.936301 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:46.110749 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.174s	user 0.123s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":11439,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30241,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23296,"update_count":2500}
I20260812 06:18:46.111459 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:46.161430 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.050s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22690,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.161906 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:46.312809 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.151s	user 0.091s	sys 0.054s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":684,"lbm_read_time_us":11097,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23231,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:46.313522 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:46.364384 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.051s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21874,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.364969 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:46.378268 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.378975 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:46.573174 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.194s	user 0.134s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":11649,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29553,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:46.573937 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:46.624764 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.051s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22469,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.625322 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:46.637475 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.638223 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:46.791633 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.153s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":10541,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30571,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:46.792299 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=14.095187
I20260812 06:18:46.843389 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.051s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20143,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.844038 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:46.855734 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.856253 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:46.887028 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushMRSOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1121,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1697,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:46.887727 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207): free 129320783 bytes of WAL
I20260812 06:18:46.887961 20065 log_reader.cc:385] T c9cb9c317e1d4a3fa594ab87d497f207: removed 13 log segments from log reader
I20260812 06:18:46.888007 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000028 (ops 133-137)
I20260812 06:18:46.888043 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000029 (ops 138-142)
I20260812 06:18:46.888105 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000030 (ops 143-147)
I20260812 06:18:46.888140 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000031 (ops 148-152)
I20260812 06:18:46.888181 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000032 (ops 153-156)
I20260812 06:18:46.888240 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000033 (ops 157-161)
I20260812 06:18:46.888281 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000034 (ops 162-166)
I20260812 06:18:46.888322 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000035 (ops 167-170)
I20260812 06:18:46.888360 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000036 (ops 171-175)
I20260812 06:18:46.888401 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000037 (ops 176-180)
I20260812 06:18:46.888438 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000038 (ops 181-185)
I20260812 06:18:46.888478 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000039 (ops 186-190)
I20260812 06:18:46.888514 20065 log.cc:1079] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: Deleting log segment in path: /tmp/dist-test-taskZ7174D/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516413247-19592-0/minicluster-data/ts-0-root/wals/c9cb9c317e1d4a3fa594ab87d497f207/wal-000000040 (ops 191-195)
I20260812 06:18:46.916558 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: LogGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:46.917079 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207): 492 bytes on disk
I20260812 06:18:46.917608 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: UndoDeltaBlockGCOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.918387 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=3.181125
I20260812 06:18:46.944074 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4832,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.944625 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=2.188937
I20260812 06:18:46.954398 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: FlushDeltaMemStoresOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3872,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.954831 20167 maintenance_manager.cc:419] P 8baf0a9e7184412297bb44eb59d8e300: Scheduling MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207): perf score=1.000000
I20260812 06:18:47.021413 19592 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.764s	user 1.799s	sys 0.147s
I20260812 06:18:47.122466 19592 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.101s	user 0.001s	sys 0.000s
I20260812 06:18:47.123000 19592 tablet_server.cc:179] TabletServer@127.19.34.1:0 shutting down...
I20260812 06:18:47.165518 20065 maintenance_manager.cc:643] P 8baf0a9e7184412297bb44eb59d8e300: MajorDeltaCompactionOp(c9cb9c317e1d4a3fa594ab87d497f207) complete. Timing: real 0.211s	user 0.138s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020738,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":473,"lbm_read_time_us":17657,"lbm_reads_lt_1ms":770,"lbm_write_time_us":32457,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":31360,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:18:47.166280 19592 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:47.166555 19592 tablet_replica.cc:333] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300: stopping tablet replica
I20260812 06:18:47.166745 19592 raft_consensus.cc:2243] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.166925 19592 raft_consensus.cc:2272] T c9cb9c317e1d4a3fa594ab87d497f207 P 8baf0a9e7184412297bb44eb59d8e300 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.182004 19592 tablet_server.cc:196] TabletServer@127.19.34.1:0 shutdown complete.
I20260812 06:18:47.225562 19592 master.cc:562] Master@127.19.34.62:37407 shutting down...
I20260812 06:18:47.229265 19592 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.229425 19592 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.229476 19592 tablet_replica.cc:333] T 00000000000000000000000000000000 P 684acee5756a4dc8bdd877851f076b53: stopping tablet replica
I20260812 06:18:47.242029 19592 master.cc:584] Master@127.19.34.62:37407 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5305 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10901 ms total)

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