[==========] 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:17:28.278976 13036 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.187.62:41681
I20260812 06:17:28.280709 13036 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:17:28.281512 13036 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:28.289637 13043 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:17:28.289680 13036 server_base.cc:1061] running on GCE node
W20260812 06:17:28.289598 13044 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:17:28.289963 13046 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:17:28.290619 13036 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:28.290756 13036 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:17:28.290808 13036 hybrid_clock.cc:648] HybridClock initialized: now 1786515448290804 us; error 0 us; skew 500 ppm
I20260812 06:17:28.292999 13036 webserver.cc:533] Webserver started at http://127.12.187.62:39907/ using document root <none> and password file <none>
I20260812 06:17:28.293727 13036 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:28.293792 13036 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:28.294121 13036 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:28.296211 13036 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/master-0-root/instance:
uuid: "f59c67367f8b4f179ba0b5c357ca1ace"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-nfb5"
I20260812 06:17:28.300565 13036 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:17:28.303005 13053 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:17:28.304203 13036 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:28.304358 13036 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/master-0-root
uuid: "f59c67367f8b4f179ba0b5c357ca1ace"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-nfb5"
I20260812 06:17:28.304478 13036 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-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:17:28.319416 13036 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:28.320192 13036 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:17:28.320392 13036 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:28.329849 13036 rpc_server.cc:307] RPC server started. Bound to: 127.12.187.62:41681
I20260812 06:17:28.329859 13131 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.187.62:41681 every 8 connection(s)
I20260812 06:17:28.332695 13132 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:17:28.339430 13132 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace: Bootstrap starting.
I20260812 06:17:28.342408 13132 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:28.343580 13132 log.cc:826] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:28.345616 13132 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace: No bootstrap required, opened a new log
I20260812 06:17:28.349217 13132 raft_consensus.cc:359] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f59c67367f8b4f179ba0b5c357ca1ace" member_type: VOTER }
I20260812 06:17:28.349427 13132 raft_consensus.cc:385] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:28.349583 13132 raft_consensus.cc:740] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f59c67367f8b4f179ba0b5c357ca1ace, State: Initialized, Role: FOLLOWER
I20260812 06:17:28.350397 13132 consensus_queue.cc:260] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [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: "f59c67367f8b4f179ba0b5c357ca1ace" member_type: VOTER }
I20260812 06:17:28.350623 13132 raft_consensus.cc:399] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:28.350697 13132 raft_consensus.cc:493] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:28.350898 13132 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:28.351854 13132 raft_consensus.cc:515] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f59c67367f8b4f179ba0b5c357ca1ace" member_type: VOTER }
I20260812 06:17:28.352412 13132 leader_election.cc:304] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [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: f59c67367f8b4f179ba0b5c357ca1ace; no voters: 
I20260812 06:17:28.352797 13132 leader_election.cc:290] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:28.352948 13137 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:28.353226 13137 raft_consensus.cc:697] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 1 LEADER]: Becoming Leader. State: Replica: f59c67367f8b4f179ba0b5c357ca1ace, State: Running, Role: LEADER
I20260812 06:17:28.353770 13137 consensus_queue.cc:237] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [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: "f59c67367f8b4f179ba0b5c357ca1ace" member_type: VOTER }
I20260812 06:17:28.354023 13132 sys_catalog.cc:565] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:28.356120 13139 sys_catalog.cc:455] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [sys.catalog]: SysCatalogTable state changed. Reason: New leader f59c67367f8b4f179ba0b5c357ca1ace. Latest consensus state: current_term: 1 leader_uuid: "f59c67367f8b4f179ba0b5c357ca1ace" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f59c67367f8b4f179ba0b5c357ca1ace" member_type: VOTER } }
I20260812 06:17:28.356150 13138 sys_catalog.cc:455] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f59c67367f8b4f179ba0b5c357ca1ace" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f59c67367f8b4f179ba0b5c357ca1ace" member_type: VOTER } }
I20260812 06:17:28.356276 13139 sys_catalog.cc:458] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:28.356287 13138 sys_catalog.cc:458] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:28.356693 13151 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:28.356914 13036 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:28.360028 13151 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:28.365901 13151 catalog_manager.cc:1383] Generated new cluster ID: 8089af70993b4d3f8945a280fb6652c3
I20260812 06:17:28.365984 13151 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:28.383389 13151 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:28.385185 13151 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:28.391175 13151 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace: Generated new TSK 0
I20260812 06:17:28.392001 13151 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:28.422545 13036 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:28.426267 13166 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:17:28.426365 13164 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:17:28.426577 13036 server_base.cc:1061] running on GCE node
W20260812 06:17:28.426410 13168 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:17:28.426834 13036 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:28.426896 13036 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:17:28.426942 13036 hybrid_clock.cc:648] HybridClock initialized: now 1786515448426941 us; error 0 us; skew 500 ppm
I20260812 06:17:28.428011 13036 webserver.cc:533] Webserver started at http://127.12.187.1:44647/ using document root <none> and password file <none>
I20260812 06:17:28.428216 13036 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:28.428297 13036 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:28.428412 13036 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:28.428889 13036 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/instance:
uuid: "5d751be6e0294d829815623ea767d86a"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-nfb5"
I20260812 06:17:28.430562 13036 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:28.431696 13179 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:17:28.431967 13036 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:28.432030 13036 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root
uuid: "5d751be6e0294d829815623ea767d86a"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-nfb5"
I20260812 06:17:28.432120 13036 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-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:17:28.459115 13036 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:28.459626 13036 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:28.460247 13036 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:28.461364 13036 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:28.461423 13036 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:28.461503 13036 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:28.461575 13036 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:28.469558 13036 rpc_server.cc:307] RPC server started. Bound to: 127.12.187.1:46747
I20260812 06:17:28.469596 13285 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.187.1:46747 every 8 connection(s)
I20260812 06:17:28.484668 13286 heartbeater.cc:344] Connected to a master server at 127.12.187.62:41681
I20260812 06:17:28.485001 13286 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:28.485539 13286 heartbeater.cc:507] Master 127.12.187.62:41681 requested a full tablet report, sending...
I20260812 06:17:28.487337 13082 ts_manager.cc:194] Registered new tserver with Master: 5d751be6e0294d829815623ea767d86a (127.12.187.1:46747)
I20260812 06:17:28.487408 13036 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017098239s
I20260812 06:17:28.488761 13082 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37046
I20260812 06:17:28.498695 13082 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37062:
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:17:28.514667 13222 tablet_service.cc:1511] Processing CreateTablet for tablet 5f825b3c112b48db930e1c1448b9f9d6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6af17e1107ff4922b70725deabcb13f3]), partition=
I20260812 06:17:28.515250 13222 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5f825b3c112b48db930e1c1448b9f9d6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:28.517984 13304 tablet_bootstrap.cc:492] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Bootstrap starting.
I20260812 06:17:28.519390 13304 tablet_bootstrap.cc:654] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:28.520635 13304 tablet_bootstrap.cc:492] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: No bootstrap required, opened a new log
I20260812 06:17:28.520777 13304 ts_tablet_manager.cc:1403] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:28.521348 13304 raft_consensus.cc:359] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d751be6e0294d829815623ea767d86a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 46747 } }
I20260812 06:17:28.521490 13304 raft_consensus.cc:385] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:28.521538 13304 raft_consensus.cc:740] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5d751be6e0294d829815623ea767d86a, State: Initialized, Role: FOLLOWER
I20260812 06:17:28.521674 13304 consensus_queue.cc:260] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [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: "5d751be6e0294d829815623ea767d86a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 46747 } }
I20260812 06:17:28.521790 13304 raft_consensus.cc:399] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:28.521847 13304 raft_consensus.cc:493] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:28.521900 13304 raft_consensus.cc:3060] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:28.522670 13304 raft_consensus.cc:515] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d751be6e0294d829815623ea767d86a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 46747 } }
I20260812 06:17:28.522827 13304 leader_election.cc:304] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [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: 5d751be6e0294d829815623ea767d86a; no voters: 
I20260812 06:17:28.523072 13304 leader_election.cc:290] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:28.523196 13306 raft_consensus.cc:2804] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:28.523402 13306 raft_consensus.cc:697] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 1 LEADER]: Becoming Leader. State: Replica: 5d751be6e0294d829815623ea767d86a, State: Running, Role: LEADER
I20260812 06:17:28.523466 13304 ts_tablet_manager.cc:1434] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:28.523586 13306 consensus_queue.cc:237] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [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: "5d751be6e0294d829815623ea767d86a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 46747 } }
I20260812 06:17:28.523829 13286 heartbeater.cc:499] Master 127.12.187.62:41681 was elected leader, sending a full tablet report...
I20260812 06:17:28.526943 13082 catalog_manager.cc:5719] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a reported cstate change: term changed from 0 to 1, leader changed from <none> to 5d751be6e0294d829815623ea767d86a (127.12.187.1). New cstate: current_term: 1 leader_uuid: "5d751be6e0294d829815623ea767d86a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d751be6e0294d829815623ea767d86a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 46747 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:28.604367 13036 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.024s	sys 0.007s
I20260812 06:17:28.720891 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=11.117440
I20260812 06:17:28.901190 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.180s	user 0.145s	sys 0.020s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":241,"delete_count":0,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1021,"drs_written":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43944,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":556,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":129,"threads_started":1,"update_count":1000}
I20260812 06:17:28.902698 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling LogGCOp(5f825b3c112b48db930e1c1448b9f9d6): free 8725963 bytes of WAL
I20260812 06:17:28.903100 13186 log_reader.cc:385] T 5f825b3c112b48db930e1c1448b9f9d6: removed 1 log segments from log reader
I20260812 06:17:28.903178 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000001 (ops 1-6)
I20260812 06:17:28.905813 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: LogGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:28.906225 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:28.935297 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.029s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.935829 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6): 12308958 bytes on disk
I20260812 06:17:28.936689 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.937292 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:29.076733 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.139s	user 0.084s	sys 0.044s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1457,"lbm_read_time_us":8742,"lbm_reads_lt_1ms":360,"lbm_write_time_us":23719,"lbm_writes_lt_1ms":343,"mutex_wait_us":315,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":388,"threads_started":5,"update_count":1500}
I20260812 06:17:29.077376 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:29.127430 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.050s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.128024 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:29.140324 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.141189 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:29.284220 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.143s	user 0.119s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":299,"lbm_read_time_us":10128,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28313,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:17:29.284926 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:29.342118 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.057s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16577,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.342768 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:29.354606 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.355136 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:29.539711 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.184s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":12386,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28238,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:29.540328 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:29.593467 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.053s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20033,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.594028 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:29.606199 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4558,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.607060 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:29.753221 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.146s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1332,"lbm_read_time_us":10836,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28565,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:29.753868 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:29.816236 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.062s	user 0.033s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24850,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.817030 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:29.835191 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.018s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.835768 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:29.981865 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.146s	user 0.113s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":674,"lbm_read_time_us":10683,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29981,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:17:29.982538 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:30.046567 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.064s	user 0.021s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24953,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.047254 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:30.059353 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4907,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.059865 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:30.232879 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.173s	user 0.107s	sys 0.066s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":530,"lbm_read_time_us":12391,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30815,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:17:30.233688 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:30.289880 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.056s	user 0.019s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21036,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.290493 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:30.302489 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.303159 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:30.448158 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.145s	user 0.104s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":751,"lbm_read_time_us":10844,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28122,"lbm_writes_lt_1ms":443,"mutex_wait_us":151,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:17:30.448832 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:30.500608 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.052s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18209,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:17:30.501341 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:30.518285 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.017s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6889,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.518887 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:30.554653 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.036s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1236,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2153,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:30.555912 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling LogGCOp(5f825b3c112b48db930e1c1448b9f9d6): free 136728219 bytes of WAL
I20260812 06:17:30.556241 13186 log_reader.cc:385] T 5f825b3c112b48db930e1c1448b9f9d6: removed 13 log segments from log reader
I20260812 06:17:30.556296 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000002 (ops 7-11)
I20260812 06:17:30.556330 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000003 (ops 12-16)
I20260812 06:17:30.556391 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000004 (ops 17-21)
I20260812 06:17:30.556455 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000005 (ops 22-26)
I20260812 06:17:30.556526 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000006 (ops 27-31)
I20260812 06:17:30.556588 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000007 (ops 32-36)
I20260812 06:17:30.556627 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000008 (ops 37-41)
I20260812 06:17:30.556664 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000009 (ops 42-46)
I20260812 06:17:30.556707 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000010 (ops 47-51)
I20260812 06:17:30.556746 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000011 (ops 52-56)
I20260812 06:17:30.556785 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000012 (ops 57-61)
I20260812 06:17:30.556830 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000013 (ops 62-66)
I20260812 06:17:30.556869 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000014 (ops 67-71)
I20260812 06:17:30.588688 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: LogGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:30.589188 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=3.181125
I20260812 06:17:30.603750 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5084,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:30.604249 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6): 482 bytes on disk
I20260812 06:17:30.604789 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.605288 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:30.616276 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.616809 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:30.822337 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.205s	user 0.151s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":789,"lbm_read_time_us":15766,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39816,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":141,"threads_started":1,"update_count":3000}
I20260812 06:17:30.823127 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:30.883149 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.060s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24313,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.883757 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:30.899125 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.899842 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:31.094090 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.194s	user 0.139s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":13366,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33550,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:31.094769 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:31.155452 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.060s	user 0.027s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":27457,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.156371 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:31.335894 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.179s	user 0.117s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":686,"lbm_read_time_us":13032,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27439,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:17:31.336611 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:31.396876 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.060s	user 0.026s	sys 0.029s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26524,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.397428 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:31.409595 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.410434 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:31.643085 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.232s	user 0.137s	sys 0.083s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":14529,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40358,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23168,"update_count":2500}
I20260812 06:17:31.643898 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:31.710510 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.066s	user 0.040s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25857,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.711202 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:31.727283 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.728077 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:31.927166 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.199s	user 0.155s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3470,"lbm_read_time_us":14885,"lbm_reads_lt_1ms":564,"lbm_write_time_us":37418,"lbm_writes_lt_1ms":543,"mutex_wait_us":2523,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:31.928085 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=11.118625
I20260812 06:17:31.978734 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.050s	user 0.029s	sys 0.017s Metrics: {"bytes_written":12840808,"delete_count":0,"lbm_write_time_us":21616,"lbm_writes_lt_1ms":316,"reinsert_count":0,"update_count":1565}
I20260812 06:17:31.979368 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:32.003232 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.024s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5652,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:32.003756 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:32.014602 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.015169 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:32.187755 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.172s	user 0.152s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733832,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":543,"lbm_read_time_us":12469,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35731,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:32.188547 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:32.244215 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.055s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19867,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.244908 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:32.259516 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5133,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.260212 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:32.296552 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.036s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1364,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2441,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:32.297410 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling LogGCOp(5f825b3c112b48db930e1c1448b9f9d6): free 124710266 bytes of WAL
I20260812 06:17:32.297657 13186 log_reader.cc:385] T 5f825b3c112b48db930e1c1448b9f9d6: removed 12 log segments from log reader
I20260812 06:17:32.297703 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000015 (ops 72-76)
I20260812 06:17:32.297756 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000016 (ops 77-81)
I20260812 06:17:32.297806 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000017 (ops 82-86)
I20260812 06:17:32.297854 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000018 (ops 87-91)
I20260812 06:17:32.297891 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000019 (ops 92-96)
I20260812 06:17:32.297951 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000020 (ops 97-101)
I20260812 06:17:32.297989 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000021 (ops 102-106)
I20260812 06:17:32.298029 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000022 (ops 107-111)
I20260812 06:17:32.298069 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000023 (ops 112-116)
I20260812 06:17:32.298106 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000024 (ops 117-121)
I20260812 06:17:32.298156 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000025 (ops 122-126)
I20260812 06:17:32.298197 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000026 (ops 127-131)
I20260812 06:17:32.327571 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: LogGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:32.328037 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6): 472 bytes on disk
I20260812 06:17:32.328518 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.329190 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=3.181125
I20260812 06:17:32.346323 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5531,"lbm_writes_lt_1ms":113,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":550}
I20260812 06:17:32.346832 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:32.362587 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6062,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.363234 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:32.550284 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.187s	user 0.150s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1083,"lbm_read_time_us":14568,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38649,"lbm_writes_lt_1ms":643,"mutex_wait_us":299,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:17:32.551183 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:32.611778 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.060s	user 0.021s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26214,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.612406 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:32.625967 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.626572 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:32.830411 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.204s	user 0.139s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":438,"lbm_read_time_us":13457,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36771,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:17:32.831364 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:32.895843 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.064s	user 0.027s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.896660 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:33.086010 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.189s	user 0.109s	sys 0.068s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":229,"lbm_read_time_us":12832,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29615,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:17:33.086822 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:33.152863 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.066s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":26354,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.153398 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:33.167868 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.168586 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:33.380741 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.212s	user 0.113s	sys 0.089s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":15709,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34388,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:33.381582 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=11.118625
I20260812 06:17:33.426429 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.045s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21198,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.427115 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:33.450076 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.023s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.450671 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:33.466288 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6116,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.467029 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:33.643220 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.176s	user 0.140s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":133,"lbm_read_time_us":13793,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35245,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:33.644091 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:33.691002 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.047s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19670,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.691877 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:33.710799 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.711403 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:33.861137 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.150s	user 0.113s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":70,"lbm_read_time_us":10117,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30506,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30208,"update_count":2000}
I20260812 06:17:33.863492 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=10.126437
I20260812 06:17:33.912580 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.049s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.913250 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:33.931195 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.018s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.931918 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:33.966472 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushMRSOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1331,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1839,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:33.967422 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling LogGCOp(5f825b3c112b48db930e1c1448b9f9d6): free 112692667 bytes of WAL
I20260812 06:17:33.967698 13186 log_reader.cc:385] T 5f825b3c112b48db930e1c1448b9f9d6: removed 11 log segments from log reader
I20260812 06:17:33.967777 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000027 (ops 132-136)
I20260812 06:17:33.967831 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000028 (ops 137-141)
I20260812 06:17:33.967892 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000029 (ops 142-146)
I20260812 06:17:33.967936 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000030 (ops 147-151)
I20260812 06:17:33.967988 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000031 (ops 152-156)
I20260812 06:17:33.968029 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000032 (ops 157-161)
I20260812 06:17:33.968078 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000033 (ops 162-166)
I20260812 06:17:33.968119 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000034 (ops 167-171)
I20260812 06:17:33.968160 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000035 (ops 172-176)
I20260812 06:17:33.968200 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000036 (ops 177-181)
I20260812 06:17:33.968240 13186 log.cc:1079] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/5f825b3c112b48db930e1c1448b9f9d6/wal-000000037 (ops 182-186)
I20260812 06:17:33.994896 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: LogGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:33.995445 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=3.181125
I20260812 06:17:34.019991 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.024s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7603,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:34.020604 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:34.031859 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.032542 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:34.241955 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.209s	user 0.162s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3184,"dirs.run_cpu_time_us":653,"dirs.run_wall_time_us":2793,"lbm_read_time_us":15617,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39729,"lbm_writes_lt_1ms":643,"mutex_wait_us":2244,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":518,"threads_started":1,"update_count":3000}
I20260812 06:17:34.242908 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=14.095187
I20260812 06:17:34.291898 13036 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.687s	user 2.139s	sys 0.117s
I20260812 06:17:34.296490 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.053s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":27290,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.297153 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6): 463 bytes on disk
I20260812 06:17:34.297650 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: UndoDeltaBlockGCOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.298322 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=2.188937
I20260812 06:17:34.313771 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: FlushDeltaMemStoresOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.314267 13288 maintenance_manager.cc:419] P 5d751be6e0294d829815623ea767d86a: Scheduling MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6): perf score=1.000000
I20260812 06:17:34.337971 13036 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.045s	user 0.002s	sys 0.000s
I20260812 06:17:34.338837 13036 tablet_server.cc:179] TabletServer@127.12.187.1:0 shutting down...
I20260812 06:17:34.451812 13186 maintenance_manager.cc:643] P 5d751be6e0294d829815623ea767d86a: MajorDeltaCompactionOp(5f825b3c112b48db930e1c1448b9f9d6) complete. Timing: real 0.137s	user 0.118s	sys 0.019s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512300,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":495,"lbm_read_time_us":8670,"lbm_reads_lt_1ms":518,"lbm_write_time_us":27757,"lbm_writes_lt_1ms":543,"mutex_wait_us":129,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:34.452731 13036 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:34.453231 13036 tablet_replica.cc:333] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a: stopping tablet replica
I20260812 06:17:34.453532 13036 raft_consensus.cc:2243] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.453840 13036 raft_consensus.cc:2272] T 5f825b3c112b48db930e1c1448b9f9d6 P 5d751be6e0294d829815623ea767d86a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.470949 13036 tablet_server.cc:196] TabletServer@127.12.187.1:0 shutdown complete.
I20260812 06:17:34.499594 13036 master.cc:562] Master@127.12.187.62:41681 shutting down...
I20260812 06:17:34.503630 13036 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.503829 13036 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.503888 13036 tablet_replica.cc:333] T 00000000000000000000000000000000 P f59c67367f8b4f179ba0b5c357ca1ace: stopping tablet replica
I20260812 06:17:34.516709 13036 master.cc:584] Master@127.12.187.62:41681 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6334 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:34.625183 13036 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.187.62:38039
I20260812 06:17:34.625671 13036 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:34.628630 13336 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:17:34.628711 13335 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:17:34.628652 13342 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:17:34.628712 13036 server_base.cc:1061] running on GCE node
I20260812 06:17:34.629050 13036 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:34.629087 13036 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:17:34.629104 13036 hybrid_clock.cc:648] HybridClock initialized: now 1786515454629104 us; error 0 us; skew 500 ppm
I20260812 06:17:34.630010 13036 webserver.cc:533] Webserver started at http://127.12.187.62:36831/ using document root <none> and password file <none>
I20260812 06:17:34.630177 13036 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:34.630223 13036 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:34.630288 13036 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:34.630707 13036 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/master-0-root/instance:
uuid: "a482b2804af84b4ba8a10c856d318761"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-nfb5"
I20260812 06:17:34.632421 13036 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:34.633435 13352 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:17:34.633769 13036 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:34.633889 13036 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/master-0-root
uuid: "a482b2804af84b4ba8a10c856d318761"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-nfb5"
I20260812 06:17:34.634037 13036 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-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:17:34.648716 13036 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:34.649222 13036 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:34.654273 13036 rpc_server.cc:307] RPC server started. Bound to: 127.12.187.62:38039
I20260812 06:17:34.655915 13442 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.187.62:38039 every 8 connection(s)
I20260812 06:17:34.656611 13445 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:17:34.658711 13445 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761: Bootstrap starting.
I20260812 06:17:34.659646 13445 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:34.660720 13445 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761: No bootstrap required, opened a new log
I20260812 06:17:34.661127 13445 raft_consensus.cc:359] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a482b2804af84b4ba8a10c856d318761" member_type: VOTER }
I20260812 06:17:34.661227 13445 raft_consensus.cc:385] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:34.661252 13445 raft_consensus.cc:740] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a482b2804af84b4ba8a10c856d318761, State: Initialized, Role: FOLLOWER
I20260812 06:17:34.661434 13445 consensus_queue.cc:260] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [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: "a482b2804af84b4ba8a10c856d318761" member_type: VOTER }
I20260812 06:17:34.661535 13445 raft_consensus.cc:399] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:34.661561 13445 raft_consensus.cc:493] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:34.661607 13445 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:34.662359 13445 raft_consensus.cc:515] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a482b2804af84b4ba8a10c856d318761" member_type: VOTER }
I20260812 06:17:34.662492 13445 leader_election.cc:304] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [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: a482b2804af84b4ba8a10c856d318761; no voters: 
I20260812 06:17:34.662672 13445 leader_election.cc:290] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:34.662812 13453 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:34.663110 13453 raft_consensus.cc:697] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 1 LEADER]: Becoming Leader. State: Replica: a482b2804af84b4ba8a10c856d318761, State: Running, Role: LEADER
I20260812 06:17:34.663183 13445 sys_catalog.cc:565] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:34.663277 13453 consensus_queue.cc:237] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [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: "a482b2804af84b4ba8a10c856d318761" member_type: VOTER }
I20260812 06:17:34.663818 13455 sys_catalog.cc:455] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a482b2804af84b4ba8a10c856d318761" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a482b2804af84b4ba8a10c856d318761" member_type: VOTER } }
I20260812 06:17:34.663861 13457 sys_catalog.cc:455] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a482b2804af84b4ba8a10c856d318761. Latest consensus state: current_term: 1 leader_uuid: "a482b2804af84b4ba8a10c856d318761" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a482b2804af84b4ba8a10c856d318761" member_type: VOTER } }
I20260812 06:17:34.663991 13455 sys_catalog.cc:458] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:34.664006 13457 sys_catalog.cc:458] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:34.664664 13462 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:34.665766 13462 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:34.665973 13036 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:34.667762 13462 catalog_manager.cc:1383] Generated new cluster ID: 85196a52863c4541acbf28d14d3dd419
I20260812 06:17:34.667822 13462 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:34.683131 13462 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:34.683769 13462 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:34.687768 13462 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761: Generated new TSK 0
I20260812 06:17:34.687961 13462 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:34.698417 13036 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:34.700853 13475 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:17:34.700975 13476 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:17:34.701031 13036 server_base.cc:1061] running on GCE node
W20260812 06:17:34.701130 13480 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:17:34.701390 13036 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:34.701436 13036 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:17:34.701454 13036 hybrid_clock.cc:648] HybridClock initialized: now 1786515454701454 us; error 0 us; skew 500 ppm
I20260812 06:17:34.702445 13036 webserver.cc:533] Webserver started at http://127.12.187.1:36189/ using document root <none> and password file <none>
I20260812 06:17:34.702647 13036 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:34.702723 13036 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:34.702823 13036 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:34.703492 13036 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/instance:
uuid: "b73a9b2cfc734cf28344235d1dc2c09a"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-nfb5"
I20260812 06:17:34.705272 13036 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:34.706247 13486 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:17:34.706522 13036 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:34.706586 13036 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root
uuid: "b73a9b2cfc734cf28344235d1dc2c09a"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-nfb5"
I20260812 06:17:34.706648 13036 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-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:17:34.711783 13036 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:34.712100 13036 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:34.712358 13036 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:34.712864 13036 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:34.712903 13036 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:34.712963 13036 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:34.713006 13036 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:34.717568 13036 rpc_server.cc:307] RPC server started. Bound to: 127.12.187.1:38103
I20260812 06:17:34.719667 13578 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.187.1:38103 every 8 connection(s)
I20260812 06:17:34.727988 13579 heartbeater.cc:344] Connected to a master server at 127.12.187.62:38039
I20260812 06:17:34.728144 13579 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:34.728433 13579 heartbeater.cc:507] Master 127.12.187.62:38039 requested a full tablet report, sending...
I20260812 06:17:34.729195 13383 ts_manager.cc:194] Registered new tserver with Master: b73a9b2cfc734cf28344235d1dc2c09a (127.12.187.1:38103)
I20260812 06:17:34.729341 13036 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011028096s
I20260812 06:17:34.730072 13383 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59366
I20260812 06:17:34.737083 13383 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59376:
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:17:34.746599 13526 tablet_service.cc:1511] Processing CreateTablet for tablet af073970204f4787aa0698ac9c618b77 (DEFAULT_TABLE table=heavy-update-compaction-test [id=9bbf3340cbd2403680872df0b774e86e]), partition=
I20260812 06:17:34.746894 13526 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet af073970204f4787aa0698ac9c618b77. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:34.749374 13601 tablet_bootstrap.cc:492] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Bootstrap starting.
I20260812 06:17:34.750280 13601 tablet_bootstrap.cc:654] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:34.751600 13601 tablet_bootstrap.cc:492] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: No bootstrap required, opened a new log
I20260812 06:17:34.751716 13601 ts_tablet_manager.cc:1403] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:34.752244 13601 raft_consensus.cc:359] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b73a9b2cfc734cf28344235d1dc2c09a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 38103 } }
I20260812 06:17:34.752367 13601 raft_consensus.cc:385] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:34.752417 13601 raft_consensus.cc:740] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b73a9b2cfc734cf28344235d1dc2c09a, State: Initialized, Role: FOLLOWER
I20260812 06:17:34.752565 13601 consensus_queue.cc:260] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [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: "b73a9b2cfc734cf28344235d1dc2c09a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 38103 } }
I20260812 06:17:34.752676 13601 raft_consensus.cc:399] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:34.752722 13601 raft_consensus.cc:493] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:34.752780 13601 raft_consensus.cc:3060] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:34.753594 13601 raft_consensus.cc:515] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b73a9b2cfc734cf28344235d1dc2c09a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 38103 } }
I20260812 06:17:34.753772 13601 leader_election.cc:304] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [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: b73a9b2cfc734cf28344235d1dc2c09a; no voters: 
I20260812 06:17:34.753998 13601 leader_election.cc:290] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:34.754101 13603 raft_consensus.cc:2804] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:34.754324 13603 raft_consensus.cc:697] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 1 LEADER]: Becoming Leader. State: Replica: b73a9b2cfc734cf28344235d1dc2c09a, State: Running, Role: LEADER
I20260812 06:17:34.754364 13601 ts_tablet_manager.cc:1434] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:34.754400 13579 heartbeater.cc:499] Master 127.12.187.62:38039 was elected leader, sending a full tablet report...
I20260812 06:17:34.754583 13603 consensus_queue.cc:237] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [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: "b73a9b2cfc734cf28344235d1dc2c09a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 38103 } }
I20260812 06:17:34.756129 13382 catalog_manager.cc:5719] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a reported cstate change: term changed from 0 to 1, leader changed from <none> to b73a9b2cfc734cf28344235d1dc2c09a (127.12.187.1). New cstate: current_term: 1 leader_uuid: "b73a9b2cfc734cf28344235d1dc2c09a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b73a9b2cfc734cf28344235d1dc2c09a" member_type: VOTER last_known_addr { host: "127.12.187.1" port: 38103 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:34.823068 13036 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.013s	sys 0.012s
I20260812 06:17:34.970145 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushMRSOp(af073970204f4787aa0698ac9c618b77): perf score=15.086190
I20260812 06:17:35.126066 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushMRSOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.156s	user 0.108s	sys 0.039s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":982,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40128,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:17:35.126820 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling LogGCOp(af073970204f4787aa0698ac9c618b77): free 20743880 bytes of WAL
I20260812 06:17:35.127118 13493 log_reader.cc:385] T af073970204f4787aa0698ac9c618b77: removed 2 log segments from log reader
I20260812 06:17:35.127194 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000001 (ops 1-6)
I20260812 06:17:35.127239 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000002 (ops 7-11)
I20260812 06:17:35.133279 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: LogGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:35.133751 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:35.157130 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.023s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.157742 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:35.333539 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.176s	user 0.111s	sys 0.063s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":524,"lbm_read_time_us":12021,"lbm_reads_lt_1ms":458,"lbm_write_time_us":27539,"lbm_writes_lt_1ms":433,"mutex_wait_us":4,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":432,"threads_started":5,"update_count":1950}
I20260812 06:17:35.334275 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77): 12719216 bytes on disk
I20260812 06:17:35.334743 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.335373 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=11.118625
I20260812 06:17:35.372303 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.037s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16123,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:35.372895 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:35.386669 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.014s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5218,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:35.387264 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:35.540035 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.153s	user 0.120s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":10221,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29000,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:35.540768 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:35.595355 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.054s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18643,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.596293 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:35.608968 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.609817 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:35.768899 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.159s	user 0.098s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":10398,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30143,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2000}
I20260812 06:17:35.769632 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:35.824676 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.055s	user 0.019s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18801,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.825369 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:35.838375 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.839001 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:36.023135 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.184s	user 0.092s	sys 0.091s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":12963,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30072,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:36.023900 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:36.070176 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.046s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.070864 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:36.190812 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.120s	user 0.086s	sys 0.033s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":356,"lbm_read_time_us":7349,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22834,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.191519 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:36.246829 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.055s	user 0.038s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.247486 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:36.259864 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.260517 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:36.398340 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.138s	user 0.101s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":9588,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27779,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:36.399106 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:36.464655 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.065s	user 0.033s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19885,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.465427 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:36.484707 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.485280 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:36.661538 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.176s	user 0.074s	sys 0.099s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":483,"lbm_read_time_us":15729,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":27731,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:17:36.662235 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:36.716162 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.054s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21156,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:36.716845 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:36.729661 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.730540 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushMRSOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:36.761399 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushMRSOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1759,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:36.762209 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling LogGCOp(af073970204f4787aa0698ac9c618b77): free 121006437 bytes of WAL
I20260812 06:17:36.762449 13493 log_reader.cc:385] T af073970204f4787aa0698ac9c618b77: removed 12 log segments from log reader
I20260812 06:17:36.762508 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000003 (ops 12-16)
I20260812 06:17:36.762564 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000004 (ops 17-21)
I20260812 06:17:36.762651 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000005 (ops 22-26)
I20260812 06:17:36.762697 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000006 (ops 27-30)
I20260812 06:17:36.762732 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000007 (ops 31-35)
I20260812 06:17:36.762765 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000008 (ops 36-40)
I20260812 06:17:36.762790 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000009 (ops 41-45)
I20260812 06:17:36.762820 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000010 (ops 46-50)
I20260812 06:17:36.762882 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000011 (ops 51-55)
I20260812 06:17:36.762974 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000012 (ops 56-60)
I20260812 06:17:36.763026 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000013 (ops 61-65)
I20260812 06:17:36.763062 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000014 (ops 66-70)
I20260812 06:17:36.791833 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: LogGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:36.792382 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=3.181125
I20260812 06:17:36.812392 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.020s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7061,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:36.812937 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:36.832154 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.019s	user 0.003s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4250,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.832890 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77): 472 bytes on disk
I20260812 06:17:36.833439 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.833968 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:37.072883 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.239s	user 0.136s	sys 0.100s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":217,"lbm_read_time_us":16774,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41450,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:17:37.073580 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=14.095187
I20260812 06:17:37.145627 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.071s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23985,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.146303 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:37.158742 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.159265 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:37.368492 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.209s	user 0.145s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":520,"lbm_read_time_us":14771,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36596,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:37.369361 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=11.118625
I20260812 06:17:37.415974 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19291,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.416808 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:37.443444 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.026s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5386,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:37.444128 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:37.455678 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:37.456280 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:37.675134 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.219s	user 0.124s	sys 0.078s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1108,"lbm_read_time_us":13099,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33391,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:17:37.675993 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=14.095187
I20260812 06:17:37.736083 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.060s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":32328,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.736711 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:37.756067 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.756846 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:37.938345 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.181s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1834,"lbm_read_time_us":11737,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36410,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:37.939105 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=11.118625
I20260812 06:17:37.991709 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.052s	user 0.016s	sys 0.036s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":24688,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.992689 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:38.010903 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.011528 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:38.165104 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.153s	user 0.125s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":922,"lbm_read_time_us":10319,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27551,"lbm_writes_lt_1ms":443,"mutex_wait_us":467,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:38.165885 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:38.210345 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12471587,"delete_count":0,"lbm_write_time_us":20710,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":306,"reinsert_count":0,"update_count":1520}
I20260812 06:17:38.211164 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:38.229496 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":6939,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:17:38.230268 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:38.377522 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.147s	user 0.114s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672274,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":510,"lbm_read_time_us":11686,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25592,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:38.378494 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:38.428031 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.049s	user 0.021s	sys 0.026s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17316,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:38.428704 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:38.441665 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.442193 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushMRSOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:38.479825 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushMRSOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.037s	user 0.025s	sys 0.008s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2133,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:38.480857 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:38.683633 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.203s	user 0.105s	sys 0.088s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":583,"lbm_read_time_us":13238,"lbm_reads_lt_1ms":464,"lbm_write_time_us":32506,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:38.684366 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling LogGCOp(af073970204f4787aa0698ac9c618b77): free 124257261 bytes of WAL
I20260812 06:17:38.684659 13493 log_reader.cc:385] T af073970204f4787aa0698ac9c618b77: removed 12 log segments from log reader
I20260812 06:17:38.684731 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000015 (ops 71-75)
I20260812 06:17:38.684824 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000016 (ops 76-80)
I20260812 06:17:38.684865 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000017 (ops 81-85)
I20260812 06:17:38.684908 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000018 (ops 86-90)
I20260812 06:17:38.684948 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000019 (ops 91-95)
I20260812 06:17:38.684988 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000020 (ops 96-100)
I20260812 06:17:38.685029 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000021 (ops 101-105)
I20260812 06:17:38.685067 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000022 (ops 106-110)
I20260812 06:17:38.685142 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000023 (ops 111-115)
I20260812 06:17:38.685186 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000024 (ops 116-120)
I20260812 06:17:38.685230 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000025 (ops 121-124)
I20260812 06:17:38.685269 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000026 (ops 125-129)
I20260812 06:17:38.713276 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: LogGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:38.713871 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=14.095187
I20260812 06:17:38.768551 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.054s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.769203 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:38.799645 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.030s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.800309 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:38.822489 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.022s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.823395 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77): 463 bytes on disk
I20260812 06:17:38.824160 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.825109 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:39.046972 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.222s	user 0.134s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":361,"lbm_read_time_us":15346,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38906,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:39.047678 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=14.095187
I20260812 06:17:39.117156 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.069s	user 0.037s	sys 0.029s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26322,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.117875 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:39.130143 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.130681 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:39.355060 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.224s	user 0.151s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":15541,"lbm_reads_lt_1ms":572,"lbm_write_time_us":38953,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:17:39.356058 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=11.118625
I20260812 06:17:39.395165 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.039s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17101,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:39.395991 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:39.414285 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6545,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:39.414856 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:39.562425 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.147s	user 0.109s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":418,"lbm_read_time_us":11717,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28047,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:17:39.563128 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:39.612102 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.049s	user 0.012s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18287,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:39.612746 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:39.626286 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.627058 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:39.780412 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.153s	user 0.132s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":10452,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28721,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:17:39.781302 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:39.825702 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.044s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19252,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:39.826354 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:39.841588 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.842454 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:40.005626 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.162s	user 0.116s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":13403,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32575,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:17:40.008011 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:40.071053 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.063s	user 0.029s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18356,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.071794 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:40.084317 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.084887 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:40.260993 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.176s	user 0.126s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":354,"lbm_read_time_us":13659,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29544,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:40.261785 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=10.126437
I20260812 06:17:40.314272 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.052s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16745,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.314941 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:40.334017 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.335003 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushMRSOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:40.367430 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushMRSOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1330,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2038,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:40.368278 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling LogGCOp(af073970204f4787aa0698ac9c618b77): free 120553638 bytes of WAL
I20260812 06:17:40.368571 13493 log_reader.cc:385] T af073970204f4787aa0698ac9c618b77: removed 12 log segments from log reader
I20260812 06:17:40.368645 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000027 (ops 130-134)
I20260812 06:17:40.368688 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000028 (ops 135-138)
I20260812 06:17:40.368724 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000029 (ops 139-143)
I20260812 06:17:40.368753 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000030 (ops 144-148)
I20260812 06:17:40.368783 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000031 (ops 149-153)
I20260812 06:17:40.368814 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000032 (ops 154-158)
I20260812 06:17:40.368844 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000033 (ops 159-162)
I20260812 06:17:40.368875 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000034 (ops 163-167)
I20260812 06:17:40.368909 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000035 (ops 168-172)
I20260812 06:17:40.368942 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000036 (ops 173-177)
I20260812 06:17:40.368970 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000037 (ops 178-182)
I20260812 06:17:40.368997 13493 log.cc:1079] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: Deleting log segment in path: /tmp/dist-test-taskVrLmOC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448266455-13036-0/minicluster-data/ts-0-root/wals/af073970204f4787aa0698ac9c618b77/wal-000000038 (ops 183-187)
I20260812 06:17:40.400009 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: LogGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:40.400580 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:40.431630 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.029s	user 0.005s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.432231 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=2.188937
I20260812 06:17:40.449462 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.450110 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77): 483 bytes on disk
I20260812 06:17:40.450600 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: UndoDeltaBlockGCOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:40.451244 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77): perf score=1.000000
I20260812 06:17:40.681284 13036 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.858s	user 2.180s	sys 0.247s
I20260812 06:17:40.686367 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: MajorDeltaCompactionOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.235s	user 0.149s	sys 0.085s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":771,"lbm_read_time_us":16872,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40905,"lbm_writes_lt_1ms":643,"mutex_wait_us":287,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19456,"thread_start_us":103,"threads_started":1,"update_count":3000}
I20260812 06:17:40.687134 13580 maintenance_manager.cc:419] P b73a9b2cfc734cf28344235d1dc2c09a: Scheduling FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77): perf score=14.095187
I20260812 06:17:40.721498 13036 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.003s	sys 0.000s
I20260812 06:17:40.722411 13036 tablet_server.cc:179] TabletServer@127.12.187.1:0 shutting down...
I20260812 06:17:40.747666 13493 maintenance_manager.cc:643] P b73a9b2cfc734cf28344235d1dc2c09a: FlushDeltaMemStoresOp(af073970204f4787aa0698ac9c618b77) complete. Timing: real 0.060s	user 0.044s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27430,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.748350 13036 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:40.748665 13036 tablet_replica.cc:333] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a: stopping tablet replica
I20260812 06:17:40.748826 13036 raft_consensus.cc:2243] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:40.761451 13036 raft_consensus.cc:2272] T af073970204f4787aa0698ac9c618b77 P b73a9b2cfc734cf28344235d1dc2c09a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:40.766299 13036 tablet_server.cc:196] TabletServer@127.12.187.1:0 shutdown complete.
I20260812 06:17:40.769565 13036 master.cc:562] Master@127.12.187.62:38039 shutting down...
I20260812 06:17:40.773207 13036 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:40.773401 13036 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:40.773487 13036 tablet_replica.cc:333] T 00000000000000000000000000000000 P a482b2804af84b4ba8a10c856d318761: stopping tablet replica
I20260812 06:17:40.785923 13036 master.cc:584] Master@127.12.187.62:38039 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6270 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12605 ms total)

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