[==========] 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 08:03:05.661650 18116 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.177.62:44219
I20260812 08:03:05.663453 18116 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 08:03:05.664521 18116 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 08:03:05.679143 18127 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 08:03:05.679430 18133 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 08:03:05.680163 18128 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 08:03:05.682075 18116 server_base.cc:1061] running on GCE node
I20260812 08:03:05.683620 18116 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 08:03:05.683876 18116 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 08:03:05.683955 18116 hybrid_clock.cc:648] HybridClock initialized: now 1786521785683950 us; error 0 us; skew 500 ppm
I20260812 08:03:05.688187 18116 webserver.cc:533] Webserver started at http://127.17.177.62:35893/ using document root <none> and password file <none>
I20260812 08:03:05.689862 18116 fs_manager.cc:362] Metadata directory not provided
I20260812 08:03:05.690065 18116 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 08:03:05.690506 18116 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 08:03:05.693958 18116 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/master-0-root/instance:
uuid: "8401415b707d46689b60709e9c12f268"
format_stamp: "Formatted at 2026-08-12 08:03:05 on dist-test-slave-7z32"
I20260812 08:03:05.701046 18116 fs_manager.cc:696] Time spent creating directory manager: real 0.006s	user 0.005s	sys 0.003s
I20260812 08:03:05.706076 18142 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:05.707696 18116 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.002s	sys 0.000s
I20260812 08:03:05.707878 18116 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/master-0-root
uuid: "8401415b707d46689b60709e9c12f268"
format_stamp: "Formatted at 2026-08-12 08:03:05 on dist-test-slave-7z32"
I20260812 08:03:05.708036 18116 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-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 08:03:05.730811 18116 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 08:03:05.731714 18116 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 08:03:05.731906 18116 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 08:03:05.744374 18116 rpc_server.cc:307] RPC server started. Bound to: 127.17.177.62:44219
I20260812 08:03:05.744408 18229 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.177.62:44219 every 8 connection(s)
I20260812 08:03:05.748102 18231 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 08:03:05.757176 18231 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268: Bootstrap starting.
I20260812 08:03:05.760804 18231 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268: Neither blocks nor log segments found. Creating new log.
I20260812 08:03:05.762234 18231 log.cc:826] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268: Log is configured to *not* fsync() on all Append() calls
I20260812 08:03:05.765390 18231 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268: No bootstrap required, opened a new log
I20260812 08:03:05.771238 18231 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8401415b707d46689b60709e9c12f268" member_type: VOTER }
I20260812 08:03:05.771571 18231 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 08:03:05.771625 18231 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8401415b707d46689b60709e9c12f268, State: Initialized, Role: FOLLOWER
I20260812 08:03:05.772490 18231 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [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: "8401415b707d46689b60709e9c12f268" member_type: VOTER }
I20260812 08:03:05.772696 18231 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 08:03:05.772753 18231 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 08:03:05.772886 18231 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 0 FOLLOWER]: Advancing to term 1
I20260812 08:03:05.774240 18231 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8401415b707d46689b60709e9c12f268" member_type: VOTER }
I20260812 08:03:05.775070 18231 leader_election.cc:304] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [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: 8401415b707d46689b60709e9c12f268; no voters: 
I20260812 08:03:05.775813 18231 leader_election.cc:290] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 08:03:05.776283 18235 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 08:03:05.776701 18235 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 1 LEADER]: Becoming Leader. State: Replica: 8401415b707d46689b60709e9c12f268, State: Running, Role: LEADER
I20260812 08:03:05.777300 18235 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [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: "8401415b707d46689b60709e9c12f268" member_type: VOTER }
I20260812 08:03:05.777856 18231 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 08:03:05.780217 18237 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8401415b707d46689b60709e9c12f268. Latest consensus state: current_term: 1 leader_uuid: "8401415b707d46689b60709e9c12f268" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8401415b707d46689b60709e9c12f268" member_type: VOTER } }
I20260812 08:03:05.780484 18237 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [sys.catalog]: This master's current role is: LEADER
I20260812 08:03:05.781234 18236 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8401415b707d46689b60709e9c12f268" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8401415b707d46689b60709e9c12f268" member_type: VOTER } }
I20260812 08:03:05.781447 18236 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [sys.catalog]: This master's current role is: LEADER
I20260812 08:03:05.782114 18251 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 08:03:05.782385 18116 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 08:03:05.786422 18251 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 08:03:05.798239 18251 catalog_manager.cc:1383] Generated new cluster ID: 3633426089e44da09df379eb75f92ffd
I20260812 08:03:05.798409 18251 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 08:03:05.836820 18251 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 08:03:05.838230 18251 catalog_manager.cc:1540] Loading token signing keys...
I20260812 08:03:05.846933 18251 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268: Generated new TSK 0
I20260812 08:03:05.848064 18251 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 08:03:05.912513 18116 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 08:03:05.916899 18273 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 08:03:05.916898 18269 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 08:03:05.916805 18268 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 08:03:05.917804 18116 server_base.cc:1061] running on GCE node
I20260812 08:03:05.918090 18116 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 08:03:05.918140 18116 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 08:03:05.918159 18116 hybrid_clock.cc:648] HybridClock initialized: now 1786521785918159 us; error 0 us; skew 500 ppm
I20260812 08:03:05.919672 18116 webserver.cc:533] Webserver started at http://127.17.177.1:41909/ using document root <none> and password file <none>
I20260812 08:03:05.919939 18116 fs_manager.cc:362] Metadata directory not provided
I20260812 08:03:05.920006 18116 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 08:03:05.920112 18116 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 08:03:05.920665 18116 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/instance:
uuid: "5c79a4fefb1c4ab1821caf08cdc236a7"
format_stamp: "Formatted at 2026-08-12 08:03:05 on dist-test-slave-7z32"
I20260812 08:03:05.922742 18116 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 08:03:05.924311 18280 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:05.924705 18116 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 08:03:05.924787 18116 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root
uuid: "5c79a4fefb1c4ab1821caf08cdc236a7"
format_stamp: "Formatted at 2026-08-12 08:03:05 on dist-test-slave-7z32"
I20260812 08:03:05.924911 18116 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-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 08:03:05.941501 18116 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 08:03:05.942312 18116 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 08:03:05.943151 18116 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 08:03:05.944525 18116 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 08:03:05.944603 18116 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:05.944694 18116 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 08:03:05.944737 18116 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:05.955848 18116 rpc_server.cc:307] RPC server started. Bound to: 127.17.177.1:40931
I20260812 08:03:05.955929 18386 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.177.1:40931 every 8 connection(s)
I20260812 08:03:05.972683 18389 heartbeater.cc:344] Connected to a master server at 127.17.177.62:44219
I20260812 08:03:05.973233 18389 heartbeater.cc:461] Registering TS with master...
I20260812 08:03:05.974022 18389 heartbeater.cc:507] Master 127.17.177.62:44219 requested a full tablet report, sending...
I20260812 08:03:05.977141 18164 ts_manager.cc:194] Registered new tserver with Master: 5c79a4fefb1c4ab1821caf08cdc236a7 (127.17.177.1:40931)
I20260812 08:03:05.977311 18116 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020279927s
I20260812 08:03:05.979125 18164 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56544
I20260812 08:03:05.994150 18164 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56552:
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 08:03:06.016315 18323 tablet_service.cc:1511] Processing CreateTablet for tablet 2eb9783f8f0b42ab82932ae32ba3e508 (DEFAULT_TABLE table=heavy-update-compaction-test [id=203c01ab0db04d2d96d7e00ee680ba62]), partition=
I20260812 08:03:06.017112 18323 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2eb9783f8f0b42ab82932ae32ba3e508. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 08:03:06.021440 18407 tablet_bootstrap.cc:492] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Bootstrap starting.
I20260812 08:03:06.022586 18407 tablet_bootstrap.cc:654] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Neither blocks nor log segments found. Creating new log.
I20260812 08:03:06.024348 18407 tablet_bootstrap.cc:492] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: No bootstrap required, opened a new log
I20260812 08:03:06.024505 18407 ts_tablet_manager.cc:1403] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 08:03:06.025084 18407 raft_consensus.cc:359] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c79a4fefb1c4ab1821caf08cdc236a7" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 40931 } }
I20260812 08:03:06.025209 18407 raft_consensus.cc:385] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 08:03:06.025234 18407 raft_consensus.cc:740] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5c79a4fefb1c4ab1821caf08cdc236a7, State: Initialized, Role: FOLLOWER
I20260812 08:03:06.025398 18407 consensus_queue.cc:260] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [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: "5c79a4fefb1c4ab1821caf08cdc236a7" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 40931 } }
I20260812 08:03:06.025487 18407 raft_consensus.cc:399] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 08:03:06.025524 18407 raft_consensus.cc:493] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 08:03:06.025638 18407 raft_consensus.cc:3060] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 08:03:06.026708 18407 raft_consensus.cc:515] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c79a4fefb1c4ab1821caf08cdc236a7" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 40931 } }
I20260812 08:03:06.026932 18407 leader_election.cc:304] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [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: 5c79a4fefb1c4ab1821caf08cdc236a7; no voters: 
I20260812 08:03:06.027244 18407 leader_election.cc:290] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 08:03:06.027596 18412 raft_consensus.cc:2804] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 08:03:06.027604 18407 ts_tablet_manager.cc:1434] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 08:03:06.028227 18389 heartbeater.cc:499] Master 127.17.177.62:44219 was elected leader, sending a full tablet report...
I20260812 08:03:06.028327 18412 raft_consensus.cc:697] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 1 LEADER]: Becoming Leader. State: Replica: 5c79a4fefb1c4ab1821caf08cdc236a7, State: Running, Role: LEADER
I20260812 08:03:06.028867 18412 consensus_queue.cc:237] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [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: "5c79a4fefb1c4ab1821caf08cdc236a7" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 40931 } }
I20260812 08:03:06.033185 18164 catalog_manager.cc:5719] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5c79a4fefb1c4ab1821caf08cdc236a7 (127.17.177.1). New cstate: current_term: 1 leader_uuid: "5c79a4fefb1c4ab1821caf08cdc236a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c79a4fefb1c4ab1821caf08cdc236a7" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 40931 } health_report { overall_health: HEALTHY } } }
I20260812 08:03:06.083499 18116 heavy-update-compaction-itest.cc:201] Time spent inserting: real 0.034s	user 0.007s	sys 0.000s
I20260812 08:03:06.207837 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=6.156503
I20260812 08:03:06.353600 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.144s	user 0.120s	sys 0.020s Metrics: {"bytes_written":4923067,"cfile_init":1,"compiler_manager_pool.queue_time_us":280,"delete_count":0,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":344,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":26125,"lbm_writes_lt_1ms":322,"peak_mem_usage":0,"reinsert_count":0,"rows_written":28,"spinlock_wait_cycles":1920,"thread_start_us":180,"threads_started":1,"update_count":600}
I20260812 08:03:06.355531 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.367574 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":1641135,"delete_count":0,"lbm_write_time_us":2625,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 08:03:06.368275 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.462791 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.094s	user 0.082s	sys 0.012s Metrics: {"cfile_cache_miss":177,"cfile_cache_miss_bytes":7711762,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1358,"lbm_read_time_us":4808,"lbm_reads_lt_1ms":213,"lbm_write_time_us":15044,"lbm_writes_lt_1ms":188,"peak_mem_usage":20033248,"reinsert_count":0,"thread_start_us":1096,"threads_started":5,"update_count":800}
I20260812 08:03:06.463986 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=2.188937
I20260812 08:03:06.488580 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.024s	user 0.001s	sys 0.019s Metrics: {"bytes_written":4102581,"delete_count":0,"lbm_write_time_us":8091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 08:03:06.489552 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling UndoDeltaBlockGCOp(2eb9783f8f0b42ab82932ae32ba3e508): 6564445 bytes on disk
I20260812 08:03:06.490324 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: UndoDeltaBlockGCOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 08:03:06.491110 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.567382 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.076s	user 0.068s	sys 0.004s Metrics: {"cfile_cache_miss":116,"cfile_cache_miss_bytes":5250268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":506,"lbm_read_time_us":2880,"lbm_reads_lt_1ms":148,"lbm_write_time_us":9790,"lbm_writes_lt_1ms":128,"peak_mem_usage":13409612,"reinsert_count":0,"spinlock_wait_cycles":36480,"update_count":500}
I20260812 08:03:06.568838 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=3.181125
I20260812 08:03:06.591363 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.022s	user 0.017s	sys 0.004s Metrics: {"bytes_written":4923066,"delete_count":0,"lbm_write_time_us":8824,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 08:03:06.593469 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.670099 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.076s	user 0.064s	sys 0.012s Metrics: {"cfile_cache_miss":136,"cfile_cache_miss_bytes":6070753,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":807,"lbm_read_time_us":3776,"lbm_reads_lt_1ms":172,"lbm_write_time_us":11412,"lbm_writes_lt_1ms":148,"mutex_wait_us":31,"peak_mem_usage":15270696,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":600}
I20260812 08:03:06.670969 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=3.181125
I20260812 08:03:06.697419 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.026s	user 0.015s	sys 0.009s Metrics: {"bytes_written":4923065,"delete_count":0,"lbm_write_time_us":9969,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 08:03:06.698189 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.777232 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.079s	user 0.067s	sys 0.012s Metrics: {"cfile_cache_miss":136,"cfile_cache_miss_bytes":6070752,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1044,"lbm_read_time_us":3958,"lbm_reads_lt_1ms":172,"lbm_write_time_us":11401,"lbm_writes_lt_1ms":148,"mutex_wait_us":73,"peak_mem_usage":15270696,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":600}
I20260812 08:03:06.778605 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=3.181125
I20260812 08:03:06.806682 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.028s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4923065,"delete_count":0,"lbm_write_time_us":10331,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":600}
I20260812 08:03:06.807710 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.821468 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.013s	user 0.004s	sys 0.003s Metrics: {"bytes_written":1641136,"delete_count":0,"lbm_write_time_us":3193,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 08:03:06.823645 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:06.857679 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.033s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1398551,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":330,"dirs.run_wall_time_us":2659,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2097,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":34}
I20260812 08:03:06.858987 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling LogGCOp(2eb9783f8f0b42ab82932ae32ba3e508): free 34540943 bytes of WAL
I20260812 08:03:06.859371 18288 log_reader.cc:385] T 2eb9783f8f0b42ab82932ae32ba3e508: removed 4 log segments from log reader
I20260812 08:03:06.859436 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000001 (ops 1-11)
I20260812 08:03:06.859481 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000002 (ops 12-21)
I20260812 08:03:06.859586 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000003 (ops 22-31)
I20260812 08:03:06.859642 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000004 (ops 32-41)
I20260812 08:03:06.868870 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: LogGCOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {}
I20260812 08:03:06.869385 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.196750
I20260812 08:03:06.883793 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":2994932,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 08:03:06.884838 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling UndoDeltaBlockGCOp(2eb9783f8f0b42ab82932ae32ba3e508): 516 bytes on disk
I20260812 08:03:06.885744 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: UndoDeltaBlockGCOp(2eb9783f8f0b42ab82932ae32ba3e508) 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 08:03:06.886608 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.003357 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.116s	user 0.084s	sys 0.032s Metrics: {"cfile_cache_miss":251,"cfile_cache_miss_bytes":10706565,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":662,"lbm_read_time_us":6405,"lbm_reads_lt_1ms":283,"lbm_write_time_us":16981,"lbm_writes_lt_1ms":261,"mutex_wait_us":113,"peak_mem_usage":29271107,"reinsert_count":0,"spinlock_wait_cycles":6272,"thread_start_us":142,"threads_started":1,"update_count":1165}
I20260812 08:03:07.004428 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=4.173312
I20260812 08:03:07.029528 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.025s	user 0.010s	sys 0.012s Metrics: {"bytes_written":6030728,"delete_count":0,"lbm_write_time_us":9481,"lbm_writes_lt_1ms":150,"reinsert_count":0,"update_count":735}
I20260812 08:03:07.030378 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.118163 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.087s	user 0.072s	sys 0.012s Metrics: {"cfile_cache_miss":163,"cfile_cache_miss_bytes":7178409,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1172,"lbm_read_time_us":6026,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":194,"lbm_write_time_us":12508,"lbm_writes_lt_1ms":175,"mutex_wait_us":63,"peak_mem_usage":18459409,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":735}
I20260812 08:03:07.119221 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=4.173312
I20260812 08:03:07.152057 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.033s	user 0.015s	sys 0.016s Metrics: {"bytes_written":5743557,"delete_count":0,"lbm_write_time_us":13461,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 08:03:07.152783 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.237102 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.084s	user 0.064s	sys 0.019s Metrics: {"cfile_cache_miss":156,"cfile_cache_miss_bytes":6891238,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2197,"lbm_read_time_us":5035,"lbm_reads_lt_1ms":188,"lbm_write_time_us":10746,"lbm_writes_lt_1ms":168,"mutex_wait_us":365,"peak_mem_usage":18172164,"reinsert_count":0,"update_count":700}
I20260812 08:03:07.237942 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=3.181125
I20260812 08:03:07.258770 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.021s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4923065,"delete_count":0,"lbm_write_time_us":9610,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":600}
I20260812 08:03:07.259536 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.332086 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.072s	user 0.053s	sys 0.016s Metrics: {"cfile_cache_miss":136,"cfile_cache_miss_bytes":6070752,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2230,"lbm_read_time_us":3835,"lbm_reads_lt_1ms":172,"lbm_write_time_us":10142,"lbm_writes_lt_1ms":148,"mutex_wait_us":570,"peak_mem_usage":15270696,"reinsert_count":0,"spinlock_wait_cycles":97920,"update_count":600}
I20260812 08:03:07.332624 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=2.188937
I20260812 08:03:07.352859 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102581,"delete_count":0,"lbm_write_time_us":6664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 08:03:07.353565 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.393000 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.039s	user 0.032s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":832,"dirs.run_wall_time_us":3971,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2533,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1280}
I20260812 08:03:07.394331 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling LogGCOp(2eb9783f8f0b42ab82932ae32ba3e508): free 25936597 bytes of WAL
I20260812 08:03:07.394687 18288 log_reader.cc:385] T 2eb9783f8f0b42ab82932ae32ba3e508: removed 3 log segments from log reader
I20260812 08:03:07.394776 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000005 (ops 42-51)
I20260812 08:03:07.394858 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000006 (ops 52-61)
I20260812 08:03:07.394922 18288 log.cc:1079] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/2eb9783f8f0b42ab82932ae32ba3e508/wal-000000007 (ops 62-71)
I20260812 08:03:07.400655 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: LogGCOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 08:03:07.401368 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.196750
I20260812 08:03:07.418372 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3159028,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 08:03:07.419198 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling UndoDeltaBlockGCOp(2eb9783f8f0b42ab82932ae32ba3e508): 462 bytes on disk
I20260812 08:03:07.420163 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: UndoDeltaBlockGCOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 08:03:07.420948 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.523965 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.103s	user 0.084s	sys 0.017s Metrics: {"cfile_cache_miss":194,"cfile_cache_miss_bytes":8409168,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":805,"lbm_read_time_us":6316,"lbm_reads_lt_1ms":226,"lbm_write_time_us":15703,"lbm_writes_lt_1ms":205,"mutex_wait_us":41,"peak_mem_usage":22811611,"reinsert_count":0,"spinlock_wait_cycles":22400,"thread_start_us":130,"threads_started":1,"update_count":885}
I20260812 08:03:07.525189 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=3.181125
I20260812 08:03:07.547457 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.022s	user 0.017s	sys 0.004s Metrics: {"bytes_written":5210239,"delete_count":0,"lbm_write_time_us":8027,"lbm_writes_lt_1ms":130,"reinsert_count":0,"update_count":635}
I20260812 08:03:07.548274 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.622951 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.074s	user 0.058s	sys 0.015s Metrics: {"cfile_cache_miss":143,"cfile_cache_miss_bytes":6357926,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1010,"lbm_read_time_us":4047,"lbm_reads_lt_1ms":175,"lbm_write_time_us":10646,"lbm_writes_lt_1ms":155,"mutex_wait_us":232,"peak_mem_usage":16598325,"reinsert_count":0,"update_count":635}
I20260812 08:03:07.623831 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=3.181125
I20260812 08:03:07.644166 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.020s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4758969,"delete_count":0,"lbm_write_time_us":8515,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 08:03:07.645042 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.705341 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.060s	user 0.049s	sys 0.010s Metrics: {"cfile_cache_miss":132,"cfile_cache_miss_bytes":5906656,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":987,"lbm_read_time_us":3140,"lbm_reads_lt_1ms":164,"lbm_write_time_us":7799,"lbm_writes_lt_1ms":144,"mutex_wait_us":345,"peak_mem_usage":15106556,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":580}
I20260812 08:03:07.706317 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=2.188937
I20260812 08:03:07.728190 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.022s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102582,"delete_count":0,"lbm_write_time_us":7618,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 08:03:07.728744 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.779605 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.051s	user 0.046s	sys 0.004s Metrics: {"cfile_cache_miss":116,"cfile_cache_miss_bytes":5250269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":861,"lbm_read_time_us":2851,"lbm_reads_lt_1ms":152,"lbm_write_time_us":6172,"lbm_writes_lt_1ms":128,"mutex_wait_us":164,"peak_mem_usage":13409612,"reinsert_count":0,"spinlock_wait_cycles":160128,"update_count":500}
I20260812 08:03:07.780450 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=2.188937
I20260812 08:03:07.796062 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3282100,"delete_count":0,"lbm_write_time_us":5179,"lbm_writes_lt_1ms":83,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":400}
I20260812 08:03:07.796972 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.853966 18116 heavy-update-compaction-itest.cc:215] Time spent updating: real 1.770s	user 0.455s	sys 0.012s
I20260812 08:03:07.858137 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: MajorDeltaCompactionOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.061s	user 0.056s	sys 0.005s Metrics: {"cfile_cache_miss":96,"cfile_cache_miss_bytes":4429787,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":480,"lbm_read_time_us":3255,"lbm_reads_lt_1ms":132,"lbm_write_time_us":7921,"lbm_writes_lt_1ms":108,"mutex_wait_us":30,"peak_mem_usage":10508144,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":400}
I20260812 08:03:07.859089 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=2.188937
I20260812 08:03:07.873606 18116 heavy-update-compaction-itest.cc:251] Time spent scanning: real 0.019s	user 0.002s	sys 0.000s
I20260812 08:03:07.874109 18116 tablet_server.cc:179] TabletServer@127.17.177.1:0 shutting down...
I20260812 08:03:07.876094 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushDeltaMemStoresOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.017s	user 0.014s	sys 0.002s Metrics: {"bytes_written":4102581,"delete_count":0,"lbm_write_time_us":6408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 08:03:07.876763 18393 maintenance_manager.cc:419] P 5c79a4fefb1c4ab1821caf08cdc236a7: Scheduling FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508): perf score=1.000000
I20260812 08:03:07.904711 18288 maintenance_manager.cc:643] P 5c79a4fefb1c4ab1821caf08cdc236a7: FlushMRSOp(2eb9783f8f0b42ab82932ae32ba3e508) complete. Timing: real 0.028s	user 0.020s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":143,"dirs.run_cpu_time_us":338,"dirs.run_wall_time_us":1944,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1955,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 08:03:07.905486 18116 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 08:03:07.906178 18116 tablet_replica.cc:333] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7: stopping tablet replica
I20260812 08:03:07.906452 18116 raft_consensus.cc:2243] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 08:03:07.906718 18116 raft_consensus.cc:2272] T 2eb9783f8f0b42ab82932ae32ba3e508 P 5c79a4fefb1c4ab1821caf08cdc236a7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 08:03:07.923508 18116 tablet_server.cc:196] TabletServer@127.17.177.1:0 shutdown complete.
I20260812 08:03:07.929507 18116 master.cc:562] Master@127.17.177.62:44219 shutting down...
I20260812 08:03:07.934352 18116 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 1 LEADER]: Raft consensus shutting down.
I20260812 08:03:07.934567 18116 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 08:03:07.934633 18116 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8401415b707d46689b60709e9c12f268: stopping tablet replica
I20260812 08:03:07.948282 18116 master.cc:584] Master@127.17.177.62:44219 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (2324 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 08:03:07.982062 18116 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.177.62:34951
I20260812 08:03:07.982729 18116 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 08:03:07.985736 18439 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 08:03:07.986248 18437 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 08:03:07.986294 18444 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 08:03:07.986689 18116 server_base.cc:1061] running on GCE node
I20260812 08:03:07.987238 18116 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 08:03:07.987322 18116 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 08:03:07.987349 18116 hybrid_clock.cc:648] HybridClock initialized: now 1786521787987347 us; error 0 us; skew 500 ppm
I20260812 08:03:07.988515 18116 webserver.cc:533] Webserver started at http://127.17.177.62:39771/ using document root <none> and password file <none>
I20260812 08:03:07.988785 18116 fs_manager.cc:362] Metadata directory not provided
I20260812 08:03:07.988883 18116 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 08:03:07.988979 18116 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 08:03:07.989522 18116 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/master-0-root/instance:
uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3"
format_stamp: "Formatted at 2026-08-12 08:03:07 on dist-test-slave-7z32"
I20260812 08:03:07.991989 18116 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 08:03:07.993726 18451 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:07.994246 18116 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 08:03:07.994467 18116 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/master-0-root
uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3"
format_stamp: "Formatted at 2026-08-12 08:03:07 on dist-test-slave-7z32"
I20260812 08:03:07.994587 18116 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-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 08:03:08.016177 18116 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 08:03:08.016743 18116 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 08:03:08.023353 18116 rpc_server.cc:307] RPC server started. Bound to: 127.17.177.62:34951
I20260812 08:03:08.027081 18546 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 08:03:08.032403 18545 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.177.62:34951 every 8 connection(s)
I20260812 08:03:08.034520 18546 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3: Bootstrap starting.
I20260812 08:03:08.036113 18546 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3: Neither blocks nor log segments found. Creating new log.
I20260812 08:03:08.038117 18546 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3: No bootstrap required, opened a new log
I20260812 08:03:08.038797 18546 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3" member_type: VOTER }
I20260812 08:03:08.038971 18546 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 08:03:08.038996 18546 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8f9cfa2bfa0c4ffaae4626b217c66aa3, State: Initialized, Role: FOLLOWER
I20260812 08:03:08.039201 18546 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [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: "8f9cfa2bfa0c4ffaae4626b217c66aa3" member_type: VOTER }
I20260812 08:03:08.039307 18546 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 08:03:08.039350 18546 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 08:03:08.039412 18546 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 08:03:08.040453 18546 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3" member_type: VOTER }
I20260812 08:03:08.040930 18546 leader_election.cc:304] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [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: 8f9cfa2bfa0c4ffaae4626b217c66aa3; no voters: 
I20260812 08:03:08.041258 18546 leader_election.cc:290] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 08:03:08.041591 18549 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 08:03:08.041939 18549 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 1 LEADER]: Becoming Leader. State: Replica: 8f9cfa2bfa0c4ffaae4626b217c66aa3, State: Running, Role: LEADER
I20260812 08:03:08.042053 18546 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 08:03:08.042237 18549 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [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: "8f9cfa2bfa0c4ffaae4626b217c66aa3" member_type: VOTER }
I20260812 08:03:08.043136 18559 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8f9cfa2bfa0c4ffaae4626b217c66aa3. Latest consensus state: current_term: 1 leader_uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3" member_type: VOTER } }
I20260812 08:03:08.043191 18550 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f9cfa2bfa0c4ffaae4626b217c66aa3" member_type: VOTER } }
I20260812 08:03:08.043313 18559 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [sys.catalog]: This master's current role is: LEADER
I20260812 08:03:08.043339 18550 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [sys.catalog]: This master's current role is: LEADER
I20260812 08:03:08.043861 18572 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 08:03:08.045068 18572 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 08:03:08.045406 18116 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 08:03:08.048326 18572 catalog_manager.cc:1383] Generated new cluster ID: b77a466dd6724b38988171443ac1060f
I20260812 08:03:08.048573 18572 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 08:03:08.066742 18572 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 08:03:08.067615 18572 catalog_manager.cc:1540] Loading token signing keys...
I20260812 08:03:08.077629 18572 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3: Generated new TSK 0
I20260812 08:03:08.077935 18572 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 08:03:08.111222 18116 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 08:03:08.114647 18593 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 08:03:08.114701 18116 server_base.cc:1061] running on GCE node
W20260812 08:03:08.114674 18589 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 08:03:08.114902 18596 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 08:03:08.115682 18116 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 08:03:08.115747 18116 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 08:03:08.115768 18116 hybrid_clock.cc:648] HybridClock initialized: now 1786521788115768 us; error 0 us; skew 500 ppm
I20260812 08:03:08.117360 18116 webserver.cc:533] Webserver started at http://127.17.177.1:35531/ using document root <none> and password file <none>
I20260812 08:03:08.117666 18116 fs_manager.cc:362] Metadata directory not provided
I20260812 08:03:08.117756 18116 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 08:03:08.117882 18116 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 08:03:08.118628 18116 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/instance:
uuid: "b8bbaa8c2ac246b7aaaf8043752d5553"
format_stamp: "Formatted at 2026-08-12 08:03:08 on dist-test-slave-7z32"
I20260812 08:03:08.120994 18116 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 08:03:08.122774 18606 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:08.123381 18116 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 08:03:08.123479 18116 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root
uuid: "b8bbaa8c2ac246b7aaaf8043752d5553"
format_stamp: "Formatted at 2026-08-12 08:03:08 on dist-test-slave-7z32"
I20260812 08:03:08.123565 18116 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-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 08:03:08.147135 18116 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 08:03:08.147601 18116 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 08:03:08.147933 18116 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 08:03:08.148555 18116 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 08:03:08.148603 18116 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:08.148641 18116 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 08:03:08.148658 18116 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 08:03:08.155319 18116 rpc_server.cc:307] RPC server started. Bound to: 127.17.177.1:35145
I20260812 08:03:08.156253 18712 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.177.1:35145 every 8 connection(s)
I20260812 08:03:08.163755 18713 heartbeater.cc:344] Connected to a master server at 127.17.177.62:34951
I20260812 08:03:08.163960 18713 heartbeater.cc:461] Registering TS with master...
I20260812 08:03:08.164338 18713 heartbeater.cc:507] Master 127.17.177.62:34951 requested a full tablet report, sending...
I20260812 08:03:08.165292 18480 ts_manager.cc:194] Registered new tserver with Master: b8bbaa8c2ac246b7aaaf8043752d5553 (127.17.177.1:35145)
I20260812 08:03:08.165680 18116 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00927501s
I20260812 08:03:08.166307 18480 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59024
I20260812 08:03:08.177743 18480 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59028:
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 08:03:08.194017 18652 tablet_service.cc:1511] Processing CreateTablet for tablet 953d784de2794c0288ace4ee098104d6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0822d082528a4484a094c6affd87aad9]), partition=
I20260812 08:03:08.194492 18652 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 953d784de2794c0288ace4ee098104d6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 08:03:08.200042 18732 tablet_bootstrap.cc:492] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Bootstrap starting.
I20260812 08:03:08.201687 18732 tablet_bootstrap.cc:654] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Neither blocks nor log segments found. Creating new log.
I20260812 08:03:08.204020 18732 tablet_bootstrap.cc:492] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: No bootstrap required, opened a new log
I20260812 08:03:08.204214 18732 ts_tablet_manager.cc:1403] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 08:03:08.205103 18732 raft_consensus.cc:359] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b8bbaa8c2ac246b7aaaf8043752d5553" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 35145 } }
I20260812 08:03:08.205318 18732 raft_consensus.cc:385] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 08:03:08.205369 18732 raft_consensus.cc:740] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b8bbaa8c2ac246b7aaaf8043752d5553, State: Initialized, Role: FOLLOWER
I20260812 08:03:08.205616 18732 consensus_queue.cc:260] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [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: "b8bbaa8c2ac246b7aaaf8043752d5553" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 35145 } }
I20260812 08:03:08.206089 18732 raft_consensus.cc:399] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 08:03:08.206460 18732 raft_consensus.cc:493] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 08:03:08.206970 18732 raft_consensus.cc:3060] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 0 FOLLOWER]: Advancing to term 1
I20260812 08:03:08.208364 18732 raft_consensus.cc:515] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b8bbaa8c2ac246b7aaaf8043752d5553" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 35145 } }
I20260812 08:03:08.208604 18732 leader_election.cc:304] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [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: b8bbaa8c2ac246b7aaaf8043752d5553; no voters: 
I20260812 08:03:08.208973 18732 leader_election.cc:290] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 08:03:08.209296 18736 raft_consensus.cc:2804] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 08:03:08.209563 18713 heartbeater.cc:499] Master 127.17.177.62:34951 was elected leader, sending a full tablet report...
I20260812 08:03:08.209582 18736 raft_consensus.cc:697] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 1 LEADER]: Becoming Leader. State: Replica: b8bbaa8c2ac246b7aaaf8043752d5553, State: Running, Role: LEADER
I20260812 08:03:08.209906 18732 ts_tablet_manager.cc:1434] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Time spent starting tablet: real 0.006s	user 0.006s	sys 0.000s
I20260812 08:03:08.209841 18736 consensus_queue.cc:237] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [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: "b8bbaa8c2ac246b7aaaf8043752d5553" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 35145 } }
I20260812 08:03:08.212728 18477 catalog_manager.cc:5719] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 reported cstate change: term changed from 0 to 1, leader changed from <none> to b8bbaa8c2ac246b7aaaf8043752d5553 (127.17.177.1). New cstate: current_term: 1 leader_uuid: "b8bbaa8c2ac246b7aaaf8043752d5553" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b8bbaa8c2ac246b7aaaf8043752d5553" member_type: VOTER last_known_addr { host: "127.17.177.1" port: 35145 } health_report { overall_health: HEALTHY } } }
I20260812 08:03:08.248601 18116 heavy-update-compaction-itest.cc:201] Time spent inserting: real 0.027s	user 0.008s	sys 0.000s
I20260812 08:03:08.407348 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushMRSOp(953d784de2794c0288ace4ee098104d6): perf score=8.140878
I20260812 08:03:08.533641 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushMRSOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.126s	user 0.079s	sys 0.044s Metrics: {"bytes_written":4923065,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":304,"dirs.run_wall_time_us":1468,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":27216,"lbm_writes_lt_1ms":382,"peak_mem_usage":0,"reinsert_count":0,"rows_written":31,"update_count":600}
I20260812 08:03:08.534519 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling LogGCOp(953d784de2794c0288ace4ee098104d6): free 8604365 bytes of WAL
I20260812 08:03:08.534912 18614 log_reader.cc:385] T 953d784de2794c0288ace4ee098104d6: removed 1 log segments from log reader
I20260812 08:03:08.534974 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000001 (ops 1-11)
I20260812 08:03:08.537308 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: LogGCOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 08:03:08.537889 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling UndoDeltaBlockGCOp(953d784de2794c0288ace4ee098104d6): 9025926 bytes on disk
I20260812 08:03:08.538539 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: UndoDeltaBlockGCOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":114,"lbm_reads_lt_1ms":4}
I20260812 08:03:08.539134 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.549424 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":1641135,"delete_count":0,"lbm_write_time_us":3540,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 08:03:08.550125 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.636407 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.086s	user 0.067s	sys 0.016s Metrics: {"cfile_cache_miss":177,"cfile_cache_miss_bytes":7834695,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":722,"lbm_read_time_us":4704,"lbm_reads_lt_1ms":205,"lbm_write_time_us":11881,"lbm_writes_lt_1ms":188,"mutex_wait_us":48,"peak_mem_usage":20033248,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":448,"threads_started":5,"update_count":800}
I20260812 08:03:08.637142 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=3.181125
I20260812 08:03:08.664103 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.027s	user 0.008s	sys 0.016s Metrics: {"bytes_written":4923065,"delete_count":0,"lbm_write_time_us":11436,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":600}
I20260812 08:03:08.665004 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.673167 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.008s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1394991,"delete_count":0,"lbm_write_time_us":2198,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 08:03:08.673933 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.757129 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.083s	user 0.054s	sys 0.029s Metrics: {"cfile_cache_miss":171,"cfile_cache_miss_bytes":7588551,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":479,"lbm_read_time_us":4728,"lbm_reads_lt_1ms":207,"lbm_write_time_us":11406,"lbm_writes_lt_1ms":182,"mutex_wait_us":90,"peak_mem_usage":19787038,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":770}
I20260812 08:03:08.758188 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=3.181125
I20260812 08:03:08.777422 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4348732,"delete_count":0,"lbm_write_time_us":6882,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 08:03:08.778232 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.837618 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.059s	user 0.058s	sys 0.000s Metrics: {"cfile_cache_miss":122,"cfile_cache_miss_bytes":5619354,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":745,"lbm_read_time_us":3403,"lbm_reads_lt_1ms":154,"lbm_write_time_us":7246,"lbm_writes_lt_1ms":134,"mutex_wait_us":67,"peak_mem_usage":13655822,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":530}
I20260812 08:03:08.838524 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:08.857116 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":3569270,"delete_count":0,"lbm_write_time_us":6653,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 08:03:08.857981 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.942035 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.084s	user 0.060s	sys 0.019s Metrics: {"cfile_cache_miss":103,"cfile_cache_miss_bytes":4839892,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":914,"lbm_read_time_us":4171,"lbm_reads_lt_1ms":135,"lbm_write_time_us":8452,"lbm_writes_lt_1ms":115,"mutex_wait_us":82,"peak_mem_usage":11835773,"reinsert_count":0,"update_count":435}
I20260812 08:03:08.942886 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=3.181125
I20260812 08:03:08.960076 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4635900,"delete_count":0,"lbm_write_time_us":7185,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":565}
I20260812 08:03:08.960752 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushMRSOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:08.999689 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushMRSOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.039s	user 0.031s	sys 0.006s Metrics: {"bytes_written":1316409,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":421,"dirs.run_wall_time_us":2130,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2727,"lbm_writes_lt_1ms":39,"mutex_wait_us":55,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":3840}
I20260812 08:03:09.000739 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling UndoDeltaBlockGCOp(953d784de2794c0288ace4ee098104d6): 491 bytes on disk
I20260812 08:03:09.001592 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: UndoDeltaBlockGCOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 08:03:09.002122 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=1.196750
I20260812 08:03:09.014899 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3200052,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":81,"mutex_wait_us":183,"reinsert_count":0,"update_count":390}
I20260812 08:03:09.015736 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling LogGCOp(953d784de2794c0288ace4ee098104d6): free 25936581 bytes of WAL
I20260812 08:03:09.015969 18614 log_reader.cc:385] T 953d784de2794c0288ace4ee098104d6: removed 3 log segments from log reader
I20260812 08:03:09.016032 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000002 (ops 12-21)
I20260812 08:03:09.016064 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000003 (ops 22-31)
I20260812 08:03:09.016140 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000004 (ops 32-41)
I20260812 08:03:09.021966 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: LogGCOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 08:03:09.022398 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.113317 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.091s	user 0.074s	sys 0.016s Metrics: {"cfile_cache_miss":208,"cfile_cache_miss_bytes":9106446,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":613,"lbm_read_time_us":4347,"lbm_reads_lt_1ms":240,"lbm_write_time_us":13335,"lbm_writes_lt_1ms":219,"mutex_wait_us":27,"peak_mem_usage":24426485,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":112,"threads_started":1,"update_count":955}
I20260812 08:03:09.114177 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.132678 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.018s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4184634,"delete_count":0,"lbm_write_time_us":6009,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 08:03:09.133386 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.139050 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.005s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1271919,"delete_count":0,"lbm_write_time_us":1453,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 08:03:09.139590 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.211154 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.071s	user 0.043s	sys 0.028s Metrics: {"cfile_cache_miss":150,"cfile_cache_miss_bytes":6727048,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1206,"lbm_read_time_us":3260,"lbm_reads_lt_1ms":186,"lbm_write_time_us":9198,"lbm_writes_lt_1ms":161,"mutex_wait_us":169,"peak_mem_usage":16844535,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":665}
I20260812 08:03:09.212031 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.227855 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3651321,"delete_count":0,"lbm_write_time_us":5431,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 08:03:09.228801 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.291519 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.062s	user 0.052s	sys 0.010s Metrics: {"cfile_cache_miss":105,"cfile_cache_miss_bytes":4921943,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1066,"lbm_read_time_us":2995,"lbm_reads_lt_1ms":141,"lbm_write_time_us":7890,"lbm_writes_lt_1ms":117,"peak_mem_usage":11917843,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":445}
I20260812 08:03:09.292315 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.316798 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.024s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102582,"delete_count":0,"lbm_write_time_us":7682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 08:03:09.317844 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.390120 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.072s	user 0.054s	sys 0.016s Metrics: {"cfile_cache_miss":116,"cfile_cache_miss_bytes":5373204,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1572,"lbm_read_time_us":3356,"lbm_reads_lt_1ms":152,"lbm_write_time_us":8666,"lbm_writes_lt_1ms":128,"mutex_wait_us":324,"peak_mem_usage":13409612,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 08:03:09.391129 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.410648 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.019s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102581,"delete_count":0,"lbm_write_time_us":8253,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 08:03:09.411453 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.481092 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.069s	user 0.050s	sys 0.019s Metrics: {"cfile_cache_miss":116,"cfile_cache_miss_bytes":5373203,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1397,"lbm_read_time_us":3493,"lbm_reads_lt_1ms":152,"lbm_write_time_us":8321,"lbm_writes_lt_1ms":128,"mutex_wait_us":567,"peak_mem_usage":13409612,"reinsert_count":0,"update_count":500}
I20260812 08:03:09.481899 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.500857 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.019s	user 0.011s	sys 0.006s Metrics: {"bytes_written":4102581,"delete_count":0,"lbm_write_time_us":6889,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":500}
I20260812 08:03:09.501570 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushMRSOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.533720 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushMRSOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.032s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":360,"dirs.run_wall_time_us":1928,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2206,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 08:03:09.534698 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling LogGCOp(953d784de2794c0288ace4ee098104d6): free 25936603 bytes of WAL
I20260812 08:03:09.535035 18614 log_reader.cc:385] T 953d784de2794c0288ace4ee098104d6: removed 3 log segments from log reader
I20260812 08:03:09.535115 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000005 (ops 42-51)
I20260812 08:03:09.535166 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000006 (ops 52-61)
I20260812 08:03:09.535208 18614 log.cc:1079] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: Deleting log segment in path: /tmp/dist-test-task1j0IK4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786521785640131-18116-0/minicluster-data/ts-0-root/wals/953d784de2794c0288ace4ee098104d6/wal-000000007 (ops 62-71)
I20260812 08:03:09.541698 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: LogGCOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 08:03:09.542208 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.558684 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3282100,"delete_count":0,"lbm_write_time_us":4695,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 08:03:09.559386 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling UndoDeltaBlockGCOp(953d784de2794c0288ace4ee098104d6): 472 bytes on disk
I20260812 08:03:09.559886 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: UndoDeltaBlockGCOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 08:03:09.560436 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.652667 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.092s	user 0.080s	sys 0.012s Metrics: {"cfile_cache_miss":197,"cfile_cache_miss_bytes":8655175,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":644,"lbm_read_time_us":5423,"lbm_reads_lt_1ms":233,"lbm_write_time_us":13881,"lbm_writes_lt_1ms":208,"mutex_wait_us":5,"peak_mem_usage":22934716,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":121,"threads_started":1,"update_count":900}
I20260812 08:03:09.653429 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=3.181125
I20260812 08:03:09.674064 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4923065,"delete_count":0,"lbm_write_time_us":8267,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 08:03:09.674762 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.745841 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.071s	user 0.054s	sys 0.017s Metrics: {"cfile_cache_miss":136,"cfile_cache_miss_bytes":6193687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":643,"lbm_read_time_us":3292,"lbm_reads_lt_1ms":168,"lbm_write_time_us":10758,"lbm_writes_lt_1ms":148,"mutex_wait_us":39,"peak_mem_usage":15270696,"reinsert_count":0,"spinlock_wait_cycles":108160,"update_count":600}
I20260812 08:03:09.746716 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=3.181125
I20260812 08:03:09.773321 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.026s	user 0.010s	sys 0.012s Metrics: {"bytes_written":4923065,"delete_count":0,"lbm_write_time_us":7712,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 08:03:09.774200 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.783716 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.009s	user 0.003s	sys 0.006s Metrics: {"bytes_written":1641135,"delete_count":0,"lbm_write_time_us":2468,"lbm_writes_lt_1ms":43,"reinsert_count":0,"update_count":200}
I20260812 08:03:09.784293 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.874269 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.090s	user 0.060s	sys 0.029s Metrics: {"cfile_cache_miss":177,"cfile_cache_miss_bytes":7834695,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1356,"lbm_read_time_us":5417,"lbm_reads_lt_1ms":213,"lbm_write_time_us":12174,"lbm_writes_lt_1ms":188,"mutex_wait_us":290,"peak_mem_usage":20033248,"reinsert_count":0,"spinlock_wait_cycles":36096,"update_count":800}
I20260812 08:03:09.874935 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=3.181125
I20260812 08:03:09.892504 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4923066,"delete_count":0,"lbm_write_time_us":7090,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 08:03:09.893098 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.939136 18116 heavy-update-compaction-itest.cc:215] Time spent updating: real 1.690s	user 0.435s	sys 0.020s
I20260812 08:03:09.949502 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.056s	user 0.051s	sys 0.003s Metrics: {"cfile_cache_miss":136,"cfile_cache_miss_bytes":6193688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":3186,"lbm_reads_lt_1ms":168,"lbm_write_time_us":8022,"lbm_writes_lt_1ms":148,"peak_mem_usage":15270696,"reinsert_count":0,"update_count":600}
I20260812 08:03:09.950027 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6): perf score=2.188937
I20260812 08:03:09.959607 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: FlushDeltaMemStoresOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3282100,"delete_count":0,"lbm_write_time_us":3335,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 08:03:09.960150 18715 maintenance_manager.cc:419] P b8bbaa8c2ac246b7aaaf8043752d5553: Scheduling MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6): perf score=1.000000
I20260812 08:03:09.963254 18116 heavy-update-compaction-itest.cc:251] Time spent scanning: real 0.024s	user 0.001s	sys 0.000s
I20260812 08:03:09.963765 18116 tablet_server.cc:179] TabletServer@127.17.177.1:0 shutting down...
I20260812 08:03:10.013762 18614 maintenance_manager.cc:643] P b8bbaa8c2ac246b7aaaf8043752d5553: MajorDeltaCompactionOp(953d784de2794c0288ace4ee098104d6) complete. Timing: real 0.053s	user 0.045s	sys 0.008s Metrics: {"cfile_cache_miss":96,"cfile_cache_miss_bytes":4552722,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1213,"lbm_read_time_us":3586,"lbm_reads_lt_1ms":132,"lbm_write_time_us":5107,"lbm_writes_lt_1ms":108,"mutex_wait_us":290,"peak_mem_usage":10508144,"reinsert_count":0,"spinlock_wait_cycles":40192,"update_count":400}
I20260812 08:03:10.014461 18116 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 08:03:10.014700 18116 tablet_replica.cc:333] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553: stopping tablet replica
I20260812 08:03:10.014907 18116 raft_consensus.cc:2243] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 1 LEADER]: Raft consensus shutting down.
I20260812 08:03:10.015087 18116 raft_consensus.cc:2272] T 953d784de2794c0288ace4ee098104d6 P b8bbaa8c2ac246b7aaaf8043752d5553 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 08:03:10.030130 18116 tablet_server.cc:196] TabletServer@127.17.177.1:0 shutdown complete.
I20260812 08:03:10.035815 18116 master.cc:562] Master@127.17.177.62:34951 shutting down...
I20260812 08:03:10.040849 18116 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 08:03:10.041211 18116 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 08:03:10.041316 18116 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8f9cfa2bfa0c4ffaae4626b217c66aa3: stopping tablet replica
I20260812 08:03:10.055598 18116 master.cc:584] Master@127.17.177.62:34951 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (2103 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (4428 ms total)

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