[==========] 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:20:17.099408  8565 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.93.126:38299
I20260812 06:20:17.100353  8565 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:20:17.100929  8565 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:17.107113  8575 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:20:17.107113  8573 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:20:17.107160  8565 server_base.cc:1061] running on GCE node
W20260812 06:20:17.107409  8572 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:20:17.107956  8565 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:17.108057  8565 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:20:17.108088  8565 hybrid_clock.cc:648] HybridClock initialized: now 1786515617108086 us; error 0 us; skew 500 ppm
I20260812 06:20:17.109717  8565 webserver.cc:533] Webserver started at http://127.8.93.126:45225/ using document root <none> and password file <none>
I20260812 06:20:17.110208  8565 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:17.110263  8565 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:17.110513  8565 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:17.112071  8565 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/master-0-root/instance:
uuid: "c3e96a0492b94c7db4170a2055a0a04f"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-gp6n"
I20260812 06:20:17.115549  8565 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:17.117560  8582 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:20:17.118606  8565 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:17.118732  8565 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/master-0-root
uuid: "c3e96a0492b94c7db4170a2055a0a04f"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-gp6n"
I20260812 06:20:17.118831  8565 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-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:20:17.132254  8565 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:17.132792  8565 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:20:17.132957  8565 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:17.140494  8565 rpc_server.cc:307] RPC server started. Bound to: 127.8.93.126:38299
I20260812 06:20:17.140514  8646 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.93.126:38299 every 8 connection(s)
I20260812 06:20:17.142701  8647 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:20:17.147958  8647 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: Bootstrap starting.
I20260812 06:20:17.150296  8647 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:17.151234  8647 log.cc:826] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:17.152830  8647 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: No bootstrap required, opened a new log
I20260812 06:20:17.155634  8647 raft_consensus.cc:359] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3e96a0492b94c7db4170a2055a0a04f" member_type: VOTER }
I20260812 06:20:17.155795  8647 raft_consensus.cc:385] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:17.155925  8647 raft_consensus.cc:740] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c3e96a0492b94c7db4170a2055a0a04f, State: Initialized, Role: FOLLOWER
I20260812 06:20:17.156517  8647 consensus_queue.cc:260] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [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: "c3e96a0492b94c7db4170a2055a0a04f" member_type: VOTER }
I20260812 06:20:17.156679  8647 raft_consensus.cc:399] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:17.156754  8647 raft_consensus.cc:493] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:17.156927  8647 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:17.157727  8647 raft_consensus.cc:515] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3e96a0492b94c7db4170a2055a0a04f" member_type: VOTER }
I20260812 06:20:17.158202  8647 leader_election.cc:304] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [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: c3e96a0492b94c7db4170a2055a0a04f; no voters: 
I20260812 06:20:17.158567  8647 leader_election.cc:290] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:17.158746  8650 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:17.159003  8650 raft_consensus.cc:697] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 1 LEADER]: Becoming Leader. State: Replica: c3e96a0492b94c7db4170a2055a0a04f, State: Running, Role: LEADER
I20260812 06:20:17.159504  8650 consensus_queue.cc:237] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [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: "c3e96a0492b94c7db4170a2055a0a04f" member_type: VOTER }
I20260812 06:20:17.159544  8647 sys_catalog.cc:565] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:17.161463  8652 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [sys.catalog]: SysCatalogTable state changed. Reason: New leader c3e96a0492b94c7db4170a2055a0a04f. Latest consensus state: current_term: 1 leader_uuid: "c3e96a0492b94c7db4170a2055a0a04f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3e96a0492b94c7db4170a2055a0a04f" member_type: VOTER } }
I20260812 06:20:17.161455  8651 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c3e96a0492b94c7db4170a2055a0a04f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3e96a0492b94c7db4170a2055a0a04f" member_type: VOTER } }
I20260812 06:20:17.161595  8652 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:17.161600  8651 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:17.161880  8565 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:17.163786  8665 catalog_manager.cc:1594] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:17.163858  8665 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:17.163934  8664 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:17.164670  8664 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:17.169436  8664 catalog_manager.cc:1383] Generated new cluster ID: 53f0bf82ab594d2e8c0db63ddf093bb9
I20260812 06:20:17.169538  8664 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:17.181034  8664 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:17.182119  8664 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:17.190637  8664 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: Generated new TSK 0
I20260812 06:20:17.191322  8664 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:17.194551  8565 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:17.197528  8670 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:20:17.197568  8671 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:20:17.197656  8565 server_base.cc:1061] running on GCE node
W20260812 06:20:17.197765  8673 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:20:17.198031  8565 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:17.198091  8565 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:20:17.198113  8565 hybrid_clock.cc:648] HybridClock initialized: now 1786515617198114 us; error 0 us; skew 500 ppm
I20260812 06:20:17.199083  8565 webserver.cc:533] Webserver started at http://127.8.93.65:33039/ using document root <none> and password file <none>
I20260812 06:20:17.199249  8565 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:17.199306  8565 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:17.199384  8565 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:17.199792  8565 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/instance:
uuid: "61e45a1a8a61491795b1a6e82d1a7fda"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-gp6n"
I20260812 06:20:17.201589  8565 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:17.202780  8682 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:20:17.203088  8565 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:17.203157  8565 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root
uuid: "61e45a1a8a61491795b1a6e82d1a7fda"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-gp6n"
I20260812 06:20:17.203241  8565 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-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:20:17.218480  8565 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:17.219146  8565 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:17.219672  8565 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:17.220532  8565 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:17.220584  8565 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.220650  8565 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:17.220693  8565 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.227355  8565 rpc_server.cc:307] RPC server started. Bound to: 127.8.93.65:37349
I20260812 06:20:17.227386  8758 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.93.65:37349 every 8 connection(s)
I20260812 06:20:17.241853  8759 heartbeater.cc:344] Connected to a master server at 127.8.93.126:38299
I20260812 06:20:17.242141  8759 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:17.242661  8759 heartbeater.cc:507] Master 127.8.93.126:38299 requested a full tablet report, sending...
I20260812 06:20:17.244220  8603 ts_manager.cc:194] Registered new tserver with Master: 61e45a1a8a61491795b1a6e82d1a7fda (127.8.93.65:37349)
I20260812 06:20:17.244450  8565 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016461485s
I20260812 06:20:17.246304  8603 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44812
I20260812 06:20:17.254253  8603 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44818:
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:20:17.268990  8717 tablet_service.cc:1511] Processing CreateTablet for tablet c85523171d2340a9bed2fa5219ddd8c9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=07155bea522c43d1ada65740de9ed9db]), partition=
I20260812 06:20:17.269490  8717 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c85523171d2340a9bed2fa5219ddd8c9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:17.271766  8772 tablet_bootstrap.cc:492] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Bootstrap starting.
I20260812 06:20:17.272831  8772 tablet_bootstrap.cc:654] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:17.274057  8772 tablet_bootstrap.cc:492] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: No bootstrap required, opened a new log
I20260812 06:20:17.274158  8772 ts_tablet_manager.cc:1403] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:17.274639  8772 raft_consensus.cc:359] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61e45a1a8a61491795b1a6e82d1a7fda" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 37349 } }
I20260812 06:20:17.274758  8772 raft_consensus.cc:385] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:17.274794  8772 raft_consensus.cc:740] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 61e45a1a8a61491795b1a6e82d1a7fda, State: Initialized, Role: FOLLOWER
I20260812 06:20:17.274956  8772 consensus_queue.cc:260] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [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: "61e45a1a8a61491795b1a6e82d1a7fda" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 37349 } }
I20260812 06:20:17.275082  8772 raft_consensus.cc:399] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:17.275121  8772 raft_consensus.cc:493] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:17.275163  8772 raft_consensus.cc:3060] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:17.276099  8772 raft_consensus.cc:515] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61e45a1a8a61491795b1a6e82d1a7fda" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 37349 } }
I20260812 06:20:17.276273  8772 leader_election.cc:304] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [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: 61e45a1a8a61491795b1a6e82d1a7fda; no voters: 
I20260812 06:20:17.276473  8772 leader_election.cc:290] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:17.276582  8774 raft_consensus.cc:2804] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:17.276839  8772 ts_tablet_manager.cc:1434] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:17.276895  8774 raft_consensus.cc:697] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 1 LEADER]: Becoming Leader. State: Replica: 61e45a1a8a61491795b1a6e82d1a7fda, State: Running, Role: LEADER
I20260812 06:20:17.277268  8759 heartbeater.cc:499] Master 127.8.93.126:38299 was elected leader, sending a full tablet report...
I20260812 06:20:17.277093  8774 consensus_queue.cc:237] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [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: "61e45a1a8a61491795b1a6e82d1a7fda" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 37349 } }
I20260812 06:20:17.280375  8603 catalog_manager.cc:5719] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda reported cstate change: term changed from 0 to 1, leader changed from <none> to 61e45a1a8a61491795b1a6e82d1a7fda (127.8.93.65). New cstate: current_term: 1 leader_uuid: "61e45a1a8a61491795b1a6e82d1a7fda" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61e45a1a8a61491795b1a6e82d1a7fda" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 37349 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:17.346472  8565 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.015s	sys 0.012s
I20260812 06:20:17.478582  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=19.054940
I20260812 06:20:17.656488  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.178s	user 0.133s	sys 0.037s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":227,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":928,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42964,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":133,"threads_started":1,"update_count":1500}
I20260812 06:20:17.657574  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling LogGCOp(c85523171d2340a9bed2fa5219ddd8c9): free 20743831 bytes of WAL
I20260812 06:20:17.657917  8688 log_reader.cc:385] T c85523171d2340a9bed2fa5219ddd8c9: removed 2 log segments from log reader
I20260812 06:20:17.657985  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000001 (ops 1-6)
I20260812 06:20:17.658033  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000002 (ops 7-11)
I20260812 06:20:17.663412  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: LogGCOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:17.663743  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:17.681403  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.017s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.682022  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9): 16411393 bytes on disk
I20260812 06:20:17.682860  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.683386  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:17.826927  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.143s	user 0.117s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":469,"lbm_read_time_us":7313,"lbm_reads_lt_1ms":460,"lbm_write_time_us":22999,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":263,"threads_started":5,"update_count":2000}
I20260812 06:20:17.827466  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=11.118625
I20260812 06:20:17.857196  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.029s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12987,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:17.857721  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:17.872118  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5036,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.872846  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:17.995708  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.123s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":391,"lbm_read_time_us":7381,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24898,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:20:17.996379  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=10.126437
I20260812 06:20:18.035482  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.039s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16882,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.036018  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.050168  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5481,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.050674  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:18.169039  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.118s	user 0.106s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":8672,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22178,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27904,"update_count":2000}
I20260812 06:20:18.169673  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=10.126437
I20260812 06:20:18.213737  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.044s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15845,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.214468  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.230350  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.230872  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:18.380662  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.150s	user 0.092s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":8242,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25253,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:20:18.381356  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=11.118625
I20260812 06:20:18.418552  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.037s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14186,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.419086  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.439651  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.020s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4826,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.440162  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.450151  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.450608  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:18.618454  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.168s	user 0.109s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":627,"lbm_read_time_us":10211,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28722,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:20:18.619165  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=11.118625
I20260812 06:20:18.674779  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.055s	user 0.021s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22662,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.675282  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.689663  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.690097  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.699913  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.700356  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:18.856032  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.156s	user 0.142s	sys 0.013s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":147,"lbm_read_time_us":10013,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33346,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:20:18.856570  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=11.118625
I20260812 06:20:18.899940  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.043s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18926,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.900436  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.919231  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.019s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.919665  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:18.929626  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.930035  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:18.963987  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1594,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1640,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:18.964828  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling LogGCOp(c85523171d2340a9bed2fa5219ddd8c9): free 128414439 bytes of WAL
I20260812 06:20:18.965058  8688 log_reader.cc:385] T c85523171d2340a9bed2fa5219ddd8c9: removed 13 log segments from log reader
I20260812 06:20:18.965103  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000003 (ops 12-16)
I20260812 06:20:18.965131  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000004 (ops 17-20)
I20260812 06:20:18.965193  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000005 (ops 21-25)
I20260812 06:20:18.965240  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000006 (ops 26-30)
I20260812 06:20:18.965276  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000007 (ops 31-34)
I20260812 06:20:18.965337  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000008 (ops 35-39)
I20260812 06:20:18.965374  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000009 (ops 40-44)
I20260812 06:20:18.965415  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000010 (ops 45-48)
I20260812 06:20:18.965453  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000011 (ops 49-53)
I20260812 06:20:18.965492  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000012 (ops 54-58)
I20260812 06:20:18.965528  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000013 (ops 59-62)
I20260812 06:20:18.965564  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000014 (ops 63-67)
I20260812 06:20:18.965603  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000015 (ops 68-72)
I20260812 06:20:18.995046  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: LogGCOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:18.995618  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9): 482 bytes on disk
I20260812 06:20:18.996218  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9) 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:20:18.996719  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=4.173312
I20260812 06:20:19.023461  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.027s	user 0.013s	sys 0.012s Metrics: {"bytes_written":5579536,"delete_count":0,"lbm_write_time_us":7217,"lbm_writes_lt_1ms":139,"reinsert_count":0,"update_count":680}
I20260812 06:20:19.024019  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.196750
I20260812 06:20:19.031381  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.007s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":2563,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:20:19.031952  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:19.251173  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.219s	user 0.142s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979827,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1188,"lbm_read_time_us":16450,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36675,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:20:19.251914  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=14.095187
I20260812 06:20:19.325881  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.074s	user 0.044s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25517,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.326560  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:19.343555  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.017s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.344033  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:19.517418  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.173s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":11587,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29273,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:19.518038  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=14.095187
I20260812 06:20:19.577006  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.059s	user 0.044s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22151,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.577503  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:19.588312  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4324,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.588802  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:19.760980  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.172s	user 0.129s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":580,"lbm_read_time_us":12085,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28939,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:19.761472  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=11.118625
I20260812 06:20:19.806191  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.044s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":18180,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.806748  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:19.831908  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.025s	user 0.010s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.832384  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:19.841769  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.842190  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:20.013299  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.171s	user 0.134s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":375,"lbm_read_time_us":12900,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28569,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:20:20.013803  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=11.118625
I20260812 06:20:20.057138  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.043s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17743,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:20.057711  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:20.074390  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.016s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4855,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.075042  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:20.190768  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.116s	user 0.087s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":7337,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22491,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:20:20.191435  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=10.126437
I20260812 06:20:20.236574  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.043s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18405,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.237175  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:20.250641  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.251154  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:20.383888  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.133s	user 0.104s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":9240,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22152,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:20:20.384555  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=10.126437
I20260812 06:20:20.434055  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.049s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15626,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.434612  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:20.445225  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.445681  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:20.476284  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1430,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1817,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:20.476970  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling LogGCOp(c85523171d2340a9bed2fa5219ddd8c9): free 121006399 bytes of WAL
I20260812 06:20:20.477190  8688 log_reader.cc:385] T c85523171d2340a9bed2fa5219ddd8c9: removed 12 log segments from log reader
I20260812 06:20:20.477233  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000016 (ops 73-77)
I20260812 06:20:20.477262  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000017 (ops 78-82)
I20260812 06:20:20.477319  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000018 (ops 83-86)
I20260812 06:20:20.477370  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000019 (ops 87-91)
I20260812 06:20:20.477416  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000020 (ops 92-96)
I20260812 06:20:20.477456  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000021 (ops 97-101)
I20260812 06:20:20.477497  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000022 (ops 102-106)
I20260812 06:20:20.477538  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000023 (ops 107-111)
I20260812 06:20:20.477578  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000024 (ops 112-116)
I20260812 06:20:20.477619  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000025 (ops 117-121)
I20260812 06:20:20.477655  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000026 (ops 122-126)
I20260812 06:20:20.477695  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000027 (ops 127-131)
I20260812 06:20:20.506007  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: LogGCOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:20.506569  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=3.181125
I20260812 06:20:20.524286  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7398,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:20.524780  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9): 463 bytes on disk
I20260812 06:20:20.525200  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9) 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:20:20.525800  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:20.536485  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.011s	user 0.004s	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:20:20.537139  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:20.710194  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.173s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":802,"lbm_read_time_us":13274,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33711,"lbm_writes_lt_1ms":643,"mutex_wait_us":289,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:20:20.710872  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=14.095187
I20260812 06:20:20.764375  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.053s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22363,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.764968  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:20.776047  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4063,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.776506  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:20.934217  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.158s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1002,"lbm_read_time_us":10991,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30799,"lbm_writes_lt_1ms":543,"mutex_wait_us":449,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:20.934980  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=14.095187
I20260812 06:20:20.984477  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.049s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.985000  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:20.996551  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.997162  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:21.165302  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.168s	user 0.096s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":12189,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28268,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:20:21.169445  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=14.095187
I20260812 06:20:21.230830  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.060s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24104,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.231310  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:21.241374  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.241856  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:21.415932  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.174s	user 0.132s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":14197,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28871,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:20:21.416625  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=14.095187
I20260812 06:20:21.472766  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.056s	user 0.020s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27958,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.473323  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:21.493359  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.020s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.493906  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:21.659652  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.166s	user 0.113s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":731,"lbm_read_time_us":11514,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28136,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:20:21.660271  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=15.087375
I20260812 06:20:21.714361  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.054s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":21854,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:21.716657  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:21.745108  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.028s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5672,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.745644  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:21.755749  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.756157  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:21.788010  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushMRSOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.032s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":117,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1387,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1934,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:21.788668  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling LogGCOp(c85523171d2340a9bed2fa5219ddd8c9): free 112239554 bytes of WAL
I20260812 06:20:21.788897  8688 log_reader.cc:385] T c85523171d2340a9bed2fa5219ddd8c9: removed 11 log segments from log reader
I20260812 06:20:21.788961  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000028 (ops 132-136)
I20260812 06:20:21.789014  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000029 (ops 137-141)
I20260812 06:20:21.789074  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000030 (ops 142-146)
I20260812 06:20:21.789119  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000031 (ops 147-151)
I20260812 06:20:21.789155  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000032 (ops 152-156)
I20260812 06:20:21.789197  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000033 (ops 157-161)
I20260812 06:20:21.789235  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000034 (ops 162-166)
I20260812 06:20:21.789273  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000035 (ops 167-171)
I20260812 06:20:21.789333  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000036 (ops 172-176)
I20260812 06:20:21.789371  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000037 (ops 177-180)
I20260812 06:20:21.789412  8688 log.cc:1079] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/c85523171d2340a9bed2fa5219ddd8c9/wal-000000038 (ops 181-185)
I20260812 06:20:21.812784  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: LogGCOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:21.813421  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=3.181125
I20260812 06:20:21.834846  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.021s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6709,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:21.835348  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9): 447 bytes on disk
I20260812 06:20:21.835776  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: UndoDeltaBlockGCOp(c85523171d2340a9bed2fa5219ddd8c9) 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:20:21.836385  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:21.845494  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3503,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.845991  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:22.100123  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.254s	user 0.164s	sys 0.080s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082256,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1943,"lbm_read_time_us":19020,"lbm_reads_lt_1ms":875,"lbm_write_time_us":44496,"lbm_writes_lt_1ms":843,"mutex_wait_us":1766,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":83,"threads_started":1,"update_count":4000}
I20260812 06:20:22.100711  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=18.063937
I20260812 06:20:22.150516  8565 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.804s	user 1.767s	sys 0.128s
I20260812 06:20:22.154359  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.053s	user 0.036s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":23144,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:22.154865  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=2.188937
I20260812 06:20:22.170859  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: FlushDeltaMemStoresOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.171419  8761 maintenance_manager.cc:419] P 61e45a1a8a61491795b1a6e82d1a7fda: Scheduling MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9): perf score=1.000000
I20260812 06:20:22.223470  8565 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.005s	sys 0.000s
I20260812 06:20:22.224249  8565 tablet_server.cc:179] TabletServer@127.8.93.65:0 shutting down...
I20260812 06:20:22.321542  8688 maintenance_manager.cc:643] P 61e45a1a8a61491795b1a6e82d1a7fda: MajorDeltaCompactionOp(c85523171d2340a9bed2fa5219ddd8c9) complete. Timing: real 0.150s	user 0.090s	sys 0.059s Metrics: {"cfile_cache_hit":377,"cfile_cache_hit_bytes":15426817,"cfile_cache_miss":255,"cfile_cache_miss_bytes":13450284,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1166,"lbm_read_time_us":6608,"lbm_reads_lt_1ms":287,"lbm_write_time_us":30836,"lbm_writes_lt_1ms":643,"mutex_wait_us":288,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":223744,"update_count":3000}
I20260812 06:20:22.322255  8565 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:22.322815  8565 tablet_replica.cc:333] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda: stopping tablet replica
I20260812 06:20:22.323086  8565 raft_consensus.cc:2243] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.323417  8565 raft_consensus.cc:2272] T c85523171d2340a9bed2fa5219ddd8c9 P 61e45a1a8a61491795b1a6e82d1a7fda [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.339570  8565 tablet_server.cc:196] TabletServer@127.8.93.65:0 shutdown complete.
I20260812 06:20:22.375483  8565 master.cc:562] Master@127.8.93.126:38299 shutting down...
I20260812 06:20:22.379518  8565 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.379712  8565 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.379815  8565 tablet_replica.cc:333] T 00000000000000000000000000000000 P c3e96a0492b94c7db4170a2055a0a04f: stopping tablet replica
I20260812 06:20:22.392024  8565 master.cc:584] Master@127.8.93.126:38299 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5384 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:22.483392  8565 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.93.126:43041
I20260812 06:20:22.483825  8565 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.486032  8799 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:20:22.485978  8795 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:20:22.485985  8801 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:20:22.486003  8565 server_base.cc:1061] running on GCE node
I20260812 06:20:22.486358  8565 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.486387  8565 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:20:22.486498  8565 hybrid_clock.cc:648] HybridClock initialized: now 1786515622486497 us; error 0 us; skew 500 ppm
I20260812 06:20:22.487291  8565 webserver.cc:533] Webserver started at http://127.8.93.126:46267/ using document root <none> and password file <none>
I20260812 06:20:22.487434  8565 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.487474  8565 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.487527  8565 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.487885  8565 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/master-0-root/instance:
uuid: "3384030edbc545cabb227faa50861236"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-gp6n"
I20260812 06:20:22.489320  8565 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:22.490214  8809 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:20:22.490541  8565 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.490610  8565 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/master-0-root
uuid: "3384030edbc545cabb227faa50861236"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-gp6n"
I20260812 06:20:22.490664  8565 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-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:20:22.510529  8565 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.510872  8565 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.514818  8565 rpc_server.cc:307] RPC server started. Bound to: 127.8.93.126:43041
I20260812 06:20:22.517923  8868 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:20:22.519232  8867 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.93.126:43041 every 8 connection(s)
I20260812 06:20:22.524088  8868 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236: Bootstrap starting.
I20260812 06:20:22.524854  8868 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.525832  8868 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236: No bootstrap required, opened a new log
I20260812 06:20:22.526192  8868 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3384030edbc545cabb227faa50861236" member_type: VOTER }
I20260812 06:20:22.526273  8868 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.526295  8868 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3384030edbc545cabb227faa50861236, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.526453  8868 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [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: "3384030edbc545cabb227faa50861236" member_type: VOTER }
I20260812 06:20:22.526558  8868 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.526644  8868 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.526711  8868 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.527418  8868 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3384030edbc545cabb227faa50861236" member_type: VOTER }
I20260812 06:20:22.527529  8868 leader_election.cc:304] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [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: 3384030edbc545cabb227faa50861236; no voters: 
I20260812 06:20:22.527778  8868 leader_election.cc:290] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.527937  8871 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.528139  8871 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 1 LEADER]: Becoming Leader. State: Replica: 3384030edbc545cabb227faa50861236, State: Running, Role: LEADER
I20260812 06:20:22.528268  8868 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:22.528263  8871 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [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: "3384030edbc545cabb227faa50861236" member_type: VOTER }
I20260812 06:20:22.528789  8872 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3384030edbc545cabb227faa50861236" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3384030edbc545cabb227faa50861236" member_type: VOTER } }
I20260812 06:20:22.528898  8872 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.528806  8873 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3384030edbc545cabb227faa50861236. Latest consensus state: current_term: 1 leader_uuid: "3384030edbc545cabb227faa50861236" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3384030edbc545cabb227faa50861236" member_type: VOTER } }
I20260812 06:20:22.529181  8877 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:22.529210  8873 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.530215  8877 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:22.530364  8565 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:22.532022  8877 catalog_manager.cc:1383] Generated new cluster ID: 52e4dd59a3854cbdad59757018d1c852
I20260812 06:20:22.532090  8877 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:22.566632  8877 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:22.567195  8877 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:22.576581  8877 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236: Generated new TSK 0
I20260812 06:20:22.576768  8877 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:22.595191  8565 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.597128  8891 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:20:22.597223  8892 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:20:22.597291  8894 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:20:22.597502  8565 server_base.cc:1061] running on GCE node
I20260812 06:20:22.597723  8565 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.597772  8565 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:20:22.597815  8565 hybrid_clock.cc:648] HybridClock initialized: now 1786515622597812 us; error 0 us; skew 500 ppm
I20260812 06:20:22.598830  8565 webserver.cc:533] Webserver started at http://127.8.93.65:32855/ using document root <none> and password file <none>
I20260812 06:20:22.599009  8565 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.599071  8565 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.599179  8565 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.599617  8565 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/instance:
uuid: "55d2732a69924a0ea84321dfeec8be89"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-gp6n"
I20260812 06:20:22.601158  8565 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:22.602152  8902 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:20:22.602461  8565 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:22.602550  8565 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root
uuid: "55d2732a69924a0ea84321dfeec8be89"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-gp6n"
I20260812 06:20:22.602636  8565 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-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:20:22.610702  8565 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.611042  8565 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.611346  8565 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:22.611804  8565 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:22.611866  8565 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.611927  8565 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:22.611961  8565 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.616255  8565 rpc_server.cc:307] RPC server started. Bound to: 127.8.93.65:36513
I20260812 06:20:22.618206  8976 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.93.65:36513 every 8 connection(s)
I20260812 06:20:22.626292  8977 heartbeater.cc:344] Connected to a master server at 127.8.93.126:43041
I20260812 06:20:22.626394  8977 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:22.626657  8977 heartbeater.cc:507] Master 127.8.93.126:43041 requested a full tablet report, sending...
I20260812 06:20:22.627290  8826 ts_manager.cc:194] Registered new tserver with Master: 55d2732a69924a0ea84321dfeec8be89 (127.8.93.65:36513)
I20260812 06:20:22.627961  8826 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39956
I20260812 06:20:22.628193  8565 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011090543s
I20260812 06:20:22.635041  8826 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39962:
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:20:22.643411  8935 tablet_service.cc:1511] Processing CreateTablet for tablet 963753bb1a394ee59bad953fae4b5ece (DEFAULT_TABLE table=heavy-update-compaction-test [id=45dfd3b5ba31460d8176d746fcb85ed0]), partition=
I20260812 06:20:22.643676  8935 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 963753bb1a394ee59bad953fae4b5ece. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.645488  8989 tablet_bootstrap.cc:492] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Bootstrap starting.
I20260812 06:20:22.646485  8989 tablet_bootstrap.cc:654] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.647449  8989 tablet_bootstrap.cc:492] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: No bootstrap required, opened a new log
I20260812 06:20:22.647532  8989 ts_tablet_manager.cc:1403] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:20:22.647879  8989 raft_consensus.cc:359] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55d2732a69924a0ea84321dfeec8be89" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 36513 } }
I20260812 06:20:22.647959  8989 raft_consensus.cc:385] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.647981  8989 raft_consensus.cc:740] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 55d2732a69924a0ea84321dfeec8be89, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.648080  8989 consensus_queue.cc:260] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [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: "55d2732a69924a0ea84321dfeec8be89" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 36513 } }
I20260812 06:20:22.648136  8989 raft_consensus.cc:399] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.648159  8989 raft_consensus.cc:493] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.648186  8989 raft_consensus.cc:3060] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.648926  8989 raft_consensus.cc:515] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55d2732a69924a0ea84321dfeec8be89" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 36513 } }
I20260812 06:20:22.649087  8989 leader_election.cc:304] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [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: 55d2732a69924a0ea84321dfeec8be89; no voters: 
I20260812 06:20:22.649326  8989 leader_election.cc:290] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.649444  8991 raft_consensus.cc:2804] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.649672  8991 raft_consensus.cc:697] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 1 LEADER]: Becoming Leader. State: Replica: 55d2732a69924a0ea84321dfeec8be89, State: Running, Role: LEADER
I20260812 06:20:22.649698  8989 ts_tablet_manager.cc:1434] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:20:22.649698  8977 heartbeater.cc:499] Master 127.8.93.126:43041 was elected leader, sending a full tablet report...
I20260812 06:20:22.649821  8991 consensus_queue.cc:237] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [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: "55d2732a69924a0ea84321dfeec8be89" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 36513 } }
I20260812 06:20:22.651032  8826 catalog_manager.cc:5719] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 reported cstate change: term changed from 0 to 1, leader changed from <none> to 55d2732a69924a0ea84321dfeec8be89 (127.8.93.65). New cstate: current_term: 1 leader_uuid: "55d2732a69924a0ea84321dfeec8be89" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55d2732a69924a0ea84321dfeec8be89" member_type: VOTER last_known_addr { host: "127.8.93.65" port: 36513 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:22.705641  8565 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.008s
I20260812 06:20:22.868590  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushMRSOp(963753bb1a394ee59bad953fae4b5ece): perf score=23.023690
I20260812 06:20:23.036067  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushMRSOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.167s	user 0.118s	sys 0.047s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":842,"drs_written":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44016,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:20:23.036808  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling LogGCOp(963753bb1a394ee59bad953fae4b5ece): free 20743880 bytes of WAL
I20260812 06:20:23.037092  8909 log_reader.cc:385] T 963753bb1a394ee59bad953fae4b5ece: removed 2 log segments from log reader
I20260812 06:20:23.037164  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000001 (ops 1-6)
I20260812 06:20:23.037286  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000002 (ops 7-11)
I20260812 06:20:23.042176  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: LogGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:23.042598  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece): 20513814 bytes on disk
I20260812 06:20:23.043094  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.043710  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=3.181125
I20260812 06:20:23.066697  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4898,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:23.067167  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:23.076267  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3485,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.076689  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:23.241816  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.165s	user 0.109s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815789,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":837,"lbm_read_time_us":11582,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28561,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":364,"threads_started":5,"update_count":2500}
I20260812 06:20:23.242548  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=11.118625
I20260812 06:20:23.270941  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12334,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:23.271420  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:23.289830  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4779,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.290504  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:23.414208  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.124s	user 0.082s	sys 0.037s 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":204,"lbm_read_time_us":7235,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23559,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:23.414829  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=11.118625
I20260812 06:20:23.463227  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.048s	user 0.029s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15928,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:23.463922  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:23.489856  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.026s	user 0.000s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5788,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.490387  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:23.504863  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.505388  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:23.681265  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.176s	user 0.113s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":294,"lbm_read_time_us":14117,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27227,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:20:23.681766  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:23.744096  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.062s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22255,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.744604  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:23.755043  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4053,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.755563  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:23.940068  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.184s	user 0.129s	sys 0.052s 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":618,"lbm_read_time_us":13463,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30545,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:23.940635  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:23.997192  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.056s	user 0.019s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19171,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.997771  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:24.014477  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.014956  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:24.194927  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.180s	user 0.092s	sys 0.080s 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":149,"lbm_read_time_us":12474,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28681,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":77952,"update_count":2500}
I20260812 06:20:24.195593  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:24.252024  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.056s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23601,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.252470  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:24.271746  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.019s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.272447  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushMRSOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:24.310537  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushMRSOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.038s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":296,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2043,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:24.311164  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling LogGCOp(963753bb1a394ee59bad953fae4b5ece): free 120553319 bytes of WAL
I20260812 06:20:24.311429  8909 log_reader.cc:385] T 963753bb1a394ee59bad953fae4b5ece: removed 12 log segments from log reader
I20260812 06:20:24.311493  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000003 (ops 12-16)
I20260812 06:20:24.311530  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000004 (ops 17-21)
I20260812 06:20:24.311561  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000005 (ops 22-26)
I20260812 06:20:24.311596  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000006 (ops 27-31)
I20260812 06:20:24.311630  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000007 (ops 32-36)
I20260812 06:20:24.311659  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000008 (ops 37-40)
I20260812 06:20:24.311687  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000009 (ops 41-45)
I20260812 06:20:24.311715  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000010 (ops 46-50)
I20260812 06:20:24.311748  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000011 (ops 51-55)
I20260812 06:20:24.311790  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000012 (ops 56-60)
I20260812 06:20:24.311821  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000013 (ops 61-64)
I20260812 06:20:24.311851  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000014 (ops 65-69)
I20260812 06:20:24.342355  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: LogGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:24.342831  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece): 462 bytes on disk
I20260812 06:20:24.343255  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.343722  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:24.368943  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.025s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.369386  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:24.380067  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.380488  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:24.609792  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.229s	user 0.151s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":245,"lbm_read_time_us":14764,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36926,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:20:24.610555  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=18.063937
I20260812 06:20:24.684264  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.073s	user 0.032s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24961,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:24.684726  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:24.695902  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.696405  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:24.900079  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.204s	user 0.108s	sys 0.095s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":14801,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32836,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31616,"update_count":3000}
I20260812 06:20:24.900835  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:24.960705  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.060s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26019,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.961190  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:24.985360  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.024s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.985846  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:25.000389  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.000921  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:25.199762  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.199s	user 0.122s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":292,"lbm_read_time_us":13926,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34336,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:20:25.200505  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:25.257730  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.057s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20348,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.258239  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:25.269713  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.270385  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:25.435355  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.165s	user 0.108s	sys 0.057s 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":796,"lbm_read_time_us":11326,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26713,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:20:25.436077  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:25.485369  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21457,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.485881  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:25.497598  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.498122  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:25.686156  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.188s	user 0.148s	sys 0.040s 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":252,"lbm_read_time_us":14875,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31100,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:25.686900  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:25.741811  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.055s	user 0.029s	sys 0.022s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":19445,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.742360  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:25.759384  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.017s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.759927  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushMRSOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:25.786376  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushMRSOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1555,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:25.787009  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling LogGCOp(963753bb1a394ee59bad953fae4b5ece): free 124257299 bytes of WAL
I20260812 06:20:25.787216  8909 log_reader.cc:385] T 963753bb1a394ee59bad953fae4b5ece: removed 12 log segments from log reader
I20260812 06:20:25.787276  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000015 (ops 70-74)
I20260812 06:20:25.787324  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000016 (ops 75-79)
I20260812 06:20:25.787395  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000017 (ops 80-84)
I20260812 06:20:25.787441  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000018 (ops 85-89)
I20260812 06:20:25.787482  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000019 (ops 90-94)
I20260812 06:20:25.787521  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000020 (ops 95-99)
I20260812 06:20:25.787560  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000021 (ops 100-104)
I20260812 06:20:25.787599  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000022 (ops 105-109)
I20260812 06:20:25.787638  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000023 (ops 110-114)
I20260812 06:20:25.787676  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000024 (ops 115-118)
I20260812 06:20:25.787714  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000025 (ops 119-123)
I20260812 06:20:25.787753  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000026 (ops 124-128)
I20260812 06:20:25.815323  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: LogGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:25.815718  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:25.829854  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.014s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4225732,"delete_count":0,"lbm_write_time_us":4405,"lbm_writes_lt_1ms":106,"mutex_wait_us":691,"reinsert_count":0,"update_count":515}
I20260812 06:20:25.830291  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:25.844460  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5371,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:20:25.844933  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:26.075238  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.230s	user 0.169s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":676,"lbm_read_time_us":16156,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39039,"lbm_writes_lt_1ms":743,"mutex_wait_us":82,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:20:26.075989  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece): 473 bytes on disk
I20260812 06:20:26.077066  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.077817  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=18.063937
I20260812 06:20:26.137404  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.059s	user 0.036s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26825,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.137856  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:26.151052  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.151559  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:26.318813  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.167s	user 0.123s	sys 0.043s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":79,"lbm_read_time_us":11216,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34647,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":3000}
I20260812 06:20:26.319484  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:26.396857  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.077s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":40573,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.397306  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=6.157687
I20260812 06:20:26.421029  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.024s	user 0.018s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8343,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:26.421811  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:26.584317  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.162s	user 0.099s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":548,"lbm_read_time_us":12088,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32977,"lbm_writes_lt_1ms":643,"mutex_wait_us":272,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":3000}
I20260812 06:20:26.585017  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:26.629524  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.044s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19644,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.630143  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:26.654775  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.022s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.655287  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:26.665581  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.666210  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:26.824690  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.158s	user 0.139s	sys 0.018s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":608,"lbm_read_time_us":10282,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34787,"lbm_writes_lt_1ms":643,"mutex_wait_us":274,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:20:26.825201  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=14.095187
I20260812 06:20:26.877840  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.052s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21328,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.878346  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:26.889482  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.889916  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:27.056365  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.166s	user 0.132s	sys 0.030s 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":791,"lbm_read_time_us":11688,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30167,"lbm_writes_lt_1ms":543,"mutex_wait_us":377,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:20:27.056963  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=12.110812
I20260812 06:20:27.095628  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.038s	user 0.022s	sys 0.015s Metrics: {"bytes_written":13784348,"delete_count":0,"lbm_write_time_us":16959,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:20:27.096261  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.196750
I20260812 06:20:27.113453  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.017s	user 0.002s	sys 0.009s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:20:27.113929  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushMRSOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:27.154095  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushMRSOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.040s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1745,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1644,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:27.154845  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=3.181125
I20260812 06:20:27.169100  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:27.169571  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling LogGCOp(963753bb1a394ee59bad953fae4b5ece): free 120553644 bytes of WAL
I20260812 06:20:27.169788  8909 log_reader.cc:385] T 963753bb1a394ee59bad953fae4b5ece: removed 12 log segments from log reader
I20260812 06:20:27.169831  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000027 (ops 129-133)
I20260812 06:20:27.169858  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000028 (ops 134-138)
I20260812 06:20:27.169929  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000029 (ops 139-143)
I20260812 06:20:27.169974  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000030 (ops 144-148)
I20260812 06:20:27.170023  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000031 (ops 149-152)
I20260812 06:20:27.170086  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000032 (ops 153-157)
I20260812 06:20:27.170125  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000033 (ops 158-162)
I20260812 06:20:27.170168  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000034 (ops 163-167)
I20260812 06:20:27.170203  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000035 (ops 168-172)
I20260812 06:20:27.170243  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000036 (ops 173-177)
I20260812 06:20:27.170284  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000037 (ops 178-182)
I20260812 06:20:27.170324  8909 log.cc:1079] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: Deleting log segment in path: /tmp/dist-test-taskVL7yHN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617089023-8565-0/minicluster-data/ts-0-root/wals/963753bb1a394ee59bad953fae4b5ece/wal-000000038 (ops 183-186)
I20260812 06:20:27.194504  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: LogGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.025s	user 0.002s	sys 0.022s Metrics: {}
I20260812 06:20:27.194952  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece): 462 bytes on disk
I20260812 06:20:27.195389  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: UndoDeltaBlockGCOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.196314  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:27.215699  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5584,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.216181  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:27.226377  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.227066  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:27.436866  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.210s	user 0.127s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020805,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":498,"lbm_read_time_us":16099,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38157,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:20:27.437578  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=15.087375
I20260812 06:20:27.453533  8565 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.748s	user 1.742s	sys 0.173s
I20260812 06:20:27.473760  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":17138,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:27.474304  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece): perf score=2.188937
I20260812 06:20:27.490484  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: FlushDeltaMemStoresOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.016s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.491050  8978 maintenance_manager.cc:419] P 55d2732a69924a0ea84321dfeec8be89: Scheduling MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece): perf score=1.000000
I20260812 06:20:27.491811  8565 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.038s	user 0.003s	sys 0.000s
I20260812 06:20:27.492302  8565 tablet_server.cc:179] TabletServer@127.8.93.65:0 shutting down...
I20260812 06:20:27.609036  8909 maintenance_manager.cc:643] P 55d2732a69924a0ea84321dfeec8be89: MajorDeltaCompactionOp(963753bb1a394ee59bad953fae4b5ece) complete. Timing: real 0.118s	user 0.110s	sys 0.008s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512288,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":447,"lbm_read_time_us":7447,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24950,"lbm_writes_lt_1ms":543,"mutex_wait_us":133,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:20:27.609827  8565 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:27.610083  8565 tablet_replica.cc:333] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89: stopping tablet replica
I20260812 06:20:27.610244  8565 raft_consensus.cc:2243] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.610448  8565 raft_consensus.cc:2272] T 963753bb1a394ee59bad953fae4b5ece P 55d2732a69924a0ea84321dfeec8be89 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.614714  8565 tablet_server.cc:196] TabletServer@127.8.93.65:0 shutdown complete.
I20260812 06:20:27.654825  8565 master.cc:562] Master@127.8.93.126:43041 shutting down...
I20260812 06:20:27.657876  8565 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.658077  8565 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.658176  8565 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3384030edbc545cabb227faa50861236: stopping tablet replica
I20260812 06:20:27.670574  8565 master.cc:584] Master@127.8.93.126:43041 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5275 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10660 ms total)

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