[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:57.496073   625 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.156.126:41957
I20260812 06:17:57.497152   625 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:57.497772   625 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.504540   631 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:57.504540   630 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:57.504644   625 server_base.cc:1061] running on GCE node
W20260812 06:17:57.504863   633 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:57.505445   625 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.505581   625 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:57.505632   625 hybrid_clock.cc:648] HybridClock initialized: now 1786515477505630 us; error 0 us; skew 500 ppm
I20260812 06:17:57.507728   625 webserver.cc:533] Webserver started at http://127.0.156.126:37139/ using document root <none> and password file <none>
I20260812 06:17:57.508329   625 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.508400   625 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.508663   625 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.510504   625 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/master-0-root/instance:
uuid: "9419d87f0a0f4818b0a55ea50e464f82"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0kls"
I20260812 06:17:57.514261   625 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:57.516548   638 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.517711   625 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:57.517907   625 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/master-0-root
uuid: "9419d87f0a0f4818b0a55ea50e464f82"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0kls"
I20260812 06:17:57.518044   625 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:57.531814   625 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.532603   625 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:57.532827   625 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.542009   625 rpc_server.cc:307] RPC server started. Bound to: 127.0.156.126:41957
I20260812 06:17:57.542016   698 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.156.126:41957 every 8 connection(s)
I20260812 06:17:57.544503   699 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:57.550279   699 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82: Bootstrap starting.
I20260812 06:17:57.552829   699 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.553922   699 log.cc:826] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:57.555860   699 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82: No bootstrap required, opened a new log
I20260812 06:17:57.559024   699 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9419d87f0a0f4818b0a55ea50e464f82" member_type: VOTER }
I20260812 06:17:57.559229   699 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.559278   699 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9419d87f0a0f4818b0a55ea50e464f82, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.560006   699 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [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: "9419d87f0a0f4818b0a55ea50e464f82" member_type: VOTER }
I20260812 06:17:57.560189   699 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.560271   699 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.560448   699 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.561355   699 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9419d87f0a0f4818b0a55ea50e464f82" member_type: VOTER }
I20260812 06:17:57.561916   699 leader_election.cc:304] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [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: 9419d87f0a0f4818b0a55ea50e464f82; no voters: 
I20260812 06:17:57.562302   699 leader_election.cc:290] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.562572   704 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.562858   704 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 1 LEADER]: Becoming Leader. State: Replica: 9419d87f0a0f4818b0a55ea50e464f82, State: Running, Role: LEADER
I20260812 06:17:57.563297   704 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [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: "9419d87f0a0f4818b0a55ea50e464f82" member_type: VOTER }
I20260812 06:17:57.563563   699 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:57.565286   706 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9419d87f0a0f4818b0a55ea50e464f82. Latest consensus state: current_term: 1 leader_uuid: "9419d87f0a0f4818b0a55ea50e464f82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9419d87f0a0f4818b0a55ea50e464f82" member_type: VOTER } }
I20260812 06:17:57.565330   705 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9419d87f0a0f4818b0a55ea50e464f82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9419d87f0a0f4818b0a55ea50e464f82" member_type: VOTER } }
I20260812 06:17:57.565429   705 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.565428   706 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.565828   720 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:57.568603   720 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:57.568938   625 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:57.574036   720 catalog_manager.cc:1383] Generated new cluster ID: 8eb288e021b74a248a28c6a407e9ea1b
I20260812 06:17:57.574127   720 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:57.601445   720 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:57.602780   720 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:57.613989   720 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82: Generated new TSK 0
I20260812 06:17:57.614871   720 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:57.634087   625 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.637571   731 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:57.637683   729 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:57.637708   728 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:57.638000   625 server_base.cc:1061] running on GCE node
I20260812 06:17:57.638201   625 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.638264   625 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:57.638299   625 hybrid_clock.cc:648] HybridClock initialized: now 1786515477638299 us; error 0 us; skew 500 ppm
I20260812 06:17:57.639371   625 webserver.cc:533] Webserver started at http://127.0.156.65:43145/ using document root <none> and password file <none>
I20260812 06:17:57.639566   625 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.639643   625 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.639729   625 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.640197   625 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/instance:
uuid: "c1a6017e2fa145cbafe1d0e3f8608a6a"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0kls"
I20260812 06:17:57.641858   625 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:57.642935   736 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.643216   625 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:57.643294   625 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root
uuid: "c1a6017e2fa145cbafe1d0e3f8608a6a"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-0kls"
I20260812 06:17:57.643390   625 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:57.660277   625 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.660813   625 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.661367   625 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:57.662678   625 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:57.662731   625 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.662803   625 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:57.662846   625 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.670006   625 rpc_server.cc:307] RPC server started. Bound to: 127.0.156.65:42521
I20260812 06:17:57.670042   810 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.156.65:42521 every 8 connection(s)
I20260812 06:17:57.680563   811 heartbeater.cc:344] Connected to a master server at 127.0.156.126:41957
I20260812 06:17:57.680871   811 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:57.681361   811 heartbeater.cc:507] Master 127.0.156.126:41957 requested a full tablet report, sending...
I20260812 06:17:57.682960   659 ts_manager.cc:194] Registered new tserver with Master: c1a6017e2fa145cbafe1d0e3f8608a6a (127.0.156.65:42521)
I20260812 06:17:57.683246   625 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012543214s
I20260812 06:17:57.684248   659 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38298
I20260812 06:17:57.693887   659 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38304:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:57.710044   768 tablet_service.cc:1511] Processing CreateTablet for tablet b5037e06dd364b308543477444cfa2c2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7029eb7d1a94489aab1300ca4a3c83cd]), partition=
I20260812 06:17:57.710525   768 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b5037e06dd364b308543477444cfa2c2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:57.713104   824 tablet_bootstrap.cc:492] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Bootstrap starting.
I20260812 06:17:57.714193   824 tablet_bootstrap.cc:654] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.715689   824 tablet_bootstrap.cc:492] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: No bootstrap required, opened a new log
I20260812 06:17:57.715827   824 ts_tablet_manager.cc:1403] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:57.716311   824 raft_consensus.cc:359] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c1a6017e2fa145cbafe1d0e3f8608a6a" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 42521 } }
I20260812 06:17:57.716442   824 raft_consensus.cc:385] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.716542   824 raft_consensus.cc:740] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c1a6017e2fa145cbafe1d0e3f8608a6a, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.716745   824 consensus_queue.cc:260] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [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: "c1a6017e2fa145cbafe1d0e3f8608a6a" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 42521 } }
I20260812 06:17:57.716858   824 raft_consensus.cc:399] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.716938   824 raft_consensus.cc:493] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.717051   824 raft_consensus.cc:3060] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.717964   824 raft_consensus.cc:515] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c1a6017e2fa145cbafe1d0e3f8608a6a" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 42521 } }
I20260812 06:17:57.718145   824 leader_election.cc:304] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [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: c1a6017e2fa145cbafe1d0e3f8608a6a; no voters: 
I20260812 06:17:57.718394   824 leader_election.cc:290] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.718509   826 raft_consensus.cc:2804] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.718776   826 raft_consensus.cc:697] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 1 LEADER]: Becoming Leader. State: Replica: c1a6017e2fa145cbafe1d0e3f8608a6a, State: Running, Role: LEADER
I20260812 06:17:57.718789   824 ts_tablet_manager.cc:1434] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:57.719002   826 consensus_queue.cc:237] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [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: "c1a6017e2fa145cbafe1d0e3f8608a6a" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 42521 } }
I20260812 06:17:57.719010   811 heartbeater.cc:499] Master 127.0.156.126:41957 was elected leader, sending a full tablet report...
I20260812 06:17:57.722338   659 catalog_manager.cc:5719] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a reported cstate change: term changed from 0 to 1, leader changed from <none> to c1a6017e2fa145cbafe1d0e3f8608a6a (127.0.156.65). New cstate: current_term: 1 leader_uuid: "c1a6017e2fa145cbafe1d0e3f8608a6a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c1a6017e2fa145cbafe1d0e3f8608a6a" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 42521 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:57.795809   625 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.020s	sys 0.013s
I20260812 06:17:57.921367   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushMRSOp(b5037e06dd364b308543477444cfa2c2): perf score=15.086190
I20260812 06:17:58.085271   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushMRSOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.164s	user 0.125s	sys 0.023s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":205,"delete_count":0,"dirs.queue_time_us":33,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":795,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38169,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":131,"threads_started":1,"update_count":1450}
I20260812 06:17:58.086513   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling LogGCOp(b5037e06dd364b308543477444cfa2c2): free 20743880 bytes of WAL
I20260812 06:17:58.086853   743 log_reader.cc:385] T b5037e06dd364b308543477444cfa2c2: removed 2 log segments from log reader
I20260812 06:17:58.086938   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000001 (ops 1-6)
I20260812 06:17:58.087014   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000002 (ops 7-11)
I20260812 06:17:58.091306   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: LogGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:58.091727   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:58.113934   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.022s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6407,"lbm_writes_lt_1ms":103,"mutex_wait_us":30,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.114394   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2): 12719217 bytes on disk
I20260812 06:17:58.114924   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.115362   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:58.249763   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.134s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":597,"lbm_read_time_us":7350,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25047,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":317,"threads_started":5,"update_count":1950}
I20260812 06:17:58.250352   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:58.291167   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.041s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17216,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.291653   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:58.302693   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.303422   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:58.437882   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.134s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":9762,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26293,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:17:58.438426   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:58.482326   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17201,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.482878   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:58.494474   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.495083   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:58.629364   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.134s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":9970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26161,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2000}
I20260812 06:17:58.630059   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:58.673491   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.043s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14101,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.674093   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:58.816251   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.142s	user 0.103s	sys 0.039s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":255,"lbm_read_time_us":7853,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22381,"lbm_writes_lt_1ms":343,"mutex_wait_us":68,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":1500}
I20260812 06:17:58.817103   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:58.856294   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.039s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16344,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.856756   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:58.970669   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.114s	user 0.093s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":829,"lbm_read_time_us":6420,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19567,"lbm_writes_lt_1ms":343,"mutex_wait_us":81,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.971360   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:59.014806   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.043s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17828,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.015323   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:59.138263   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.123s	user 0.079s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":182,"lbm_read_time_us":8460,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19572,"lbm_writes_lt_1ms":343,"mutex_wait_us":92,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.139011   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:59.178227   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.039s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16582,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.178798   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:59.194725   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.195439   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:59.332574   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.137s	user 0.102s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":10265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26746,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:17:59.333333   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:17:59.378053   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.045s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15656,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.378573   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:59.389729   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.390317   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushMRSOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:59.424015   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushMRSOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1549,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2140,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:59.424882   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling LogGCOp(b5037e06dd364b308543477444cfa2c2): free 111786262 bytes of WAL
I20260812 06:17:59.425125   743 log_reader.cc:385] T b5037e06dd364b308543477444cfa2c2: removed 11 log segments from log reader
I20260812 06:17:59.425168   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000003 (ops 12-16)
I20260812 06:17:59.425222   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000004 (ops 17-21)
I20260812 06:17:59.425271   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000005 (ops 22-26)
I20260812 06:17:59.425302   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000006 (ops 27-30)
I20260812 06:17:59.425336   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000007 (ops 31-35)
I20260812 06:17:59.425396   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000008 (ops 36-40)
I20260812 06:17:59.425429   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000009 (ops 41-45)
I20260812 06:17:59.425467   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000010 (ops 46-50)
I20260812 06:17:59.425505   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000011 (ops 51-54)
I20260812 06:17:59.425544   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000012 (ops 55-59)
I20260812 06:17:59.425590   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000013 (ops 60-64)
I20260812 06:17:59.449338   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: LogGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.024s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:17:59.449847   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2): 447 bytes on disk
I20260812 06:17:59.450439   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.450978   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=3.181125
I20260812 06:17:59.471032   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.020s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7284,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:59.471505   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:59.481943   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3773,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.482471   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:59.668499   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.186s	user 0.125s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":533,"lbm_read_time_us":13311,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36311,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:17:59.669226   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=14.095187
I20260812 06:17:59.721591   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.052s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21602,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.722114   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:59.735383   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.736022   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:17:59.892316   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.156s	user 0.117s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":431,"lbm_read_time_us":9870,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31433,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:59.893045   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=11.118625
I20260812 06:17:59.927306   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.034s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14927,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:59.927973   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:17:59.943845   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5393,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.944542   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:00.097990   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.153s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1848,"lbm_read_time_us":9996,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28279,"lbm_writes_lt_1ms":443,"mutex_wait_us":668,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:00.098728   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:00.142594   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19326,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.143175   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:00.160954   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.161535   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:00.293658   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.132s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1385,"lbm_read_time_us":9763,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26089,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.294339   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:00.334857   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.040s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17581,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.335476   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:00.351884   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.352403   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:00.479063   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.126s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1341,"lbm_read_time_us":8204,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25188,"lbm_writes_lt_1ms":443,"mutex_wait_us":387,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:00.479714   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:00.522065   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.042s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15207,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.522716   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:00.533855   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.534555   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:00.672318   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.138s	user 0.117s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":9845,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26610,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:18:00.673000   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:00.721590   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.048s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17597,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.722247   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:00.733920   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.734396   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:00.886499   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.152s	user 0.124s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":12329,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24033,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2000}
I20260812 06:18:00.887408   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:00.929883   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.042s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19793,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.930491   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:00.943639   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.944278   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushMRSOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:00.979262   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushMRSOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1471,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1750,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:00.980041   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling LogGCOp(b5037e06dd364b308543477444cfa2c2): free 133024366 bytes of WAL
I20260812 06:18:00.980294   743 log_reader.cc:385] T b5037e06dd364b308543477444cfa2c2: removed 13 log segments from log reader
I20260812 06:18:00.980356   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000014 (ops 65-69)
I20260812 06:18:00.980414   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000015 (ops 70-74)
I20260812 06:18:00.980472   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000016 (ops 75-79)
I20260812 06:18:00.980517   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000017 (ops 80-84)
I20260812 06:18:00.980554   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000018 (ops 85-89)
I20260812 06:18:00.980593   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000019 (ops 90-94)
I20260812 06:18:00.980633   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000020 (ops 95-99)
I20260812 06:18:00.980679   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000021 (ops 100-104)
I20260812 06:18:00.980717   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000022 (ops 105-108)
I20260812 06:18:00.980756   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000023 (ops 109-113)
I20260812 06:18:00.980794   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000024 (ops 114-118)
I20260812 06:18:00.980834   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000025 (ops 119-123)
I20260812 06:18:00.980871   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000026 (ops 124-128)
I20260812 06:18:01.011397   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: LogGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:01.011881   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=4.173312
I20260812 06:18:01.036360   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.024s	user 0.007s	sys 0.015s Metrics: {"bytes_written":5907728,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:01.036984   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=1.196750
I20260812 06:18:01.049187   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:01.049880   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:01.263597   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.213s	user 0.133s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877298,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":299,"lbm_read_time_us":15719,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35863,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:01.265417   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2): 483 bytes on disk
I20260812 06:18:01.266597   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.267738   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=14.095187
I20260812 06:18:01.335091   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.067s	user 0.021s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23984,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.335719   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:01.346372   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.346870   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:01.526536   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.179s	user 0.128s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":12887,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31410,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:01.527321   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:01.561473   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.034s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14649,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.562119   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:01.579550   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6326,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.580096   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:01.719266   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.139s	user 0.107s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":8582,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26533,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:18:01.719909   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:01.756405   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.036s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15741,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.757109   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:01.878274   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.121s	user 0.097s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1301,"lbm_read_time_us":6987,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21434,"lbm_writes_lt_1ms":343,"mutex_wait_us":379,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":1500}
I20260812 06:18:01.879027   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:01.917657   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.038s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19587,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.918268   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:02.033162   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.115s	user 0.072s	sys 0.037s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":402,"lbm_read_time_us":7369,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18434,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":1500}
I20260812 06:18:02.033773   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:02.086760   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.053s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17857,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.087333   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:02.098536   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.099422   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:02.225054   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.125s	user 0.086s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":456,"lbm_read_time_us":7957,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23867,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:02.225915   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:02.270291   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.044s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14666,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.270985   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:02.282480   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.283125   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:02.409343   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.126s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":394,"lbm_read_time_us":10119,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22853,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:18:02.410178   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=10.126437
I20260812 06:18:02.462459   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.052s	user 0.015s	sys 0.036s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19829,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.463168   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:02.482208   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.483240   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushMRSOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:02.511674   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushMRSOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1469,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1596,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:02.512454   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling LogGCOp(b5037e06dd364b308543477444cfa2c2): free 121006647 bytes of WAL
I20260812 06:18:02.512750   743 log_reader.cc:385] T b5037e06dd364b308543477444cfa2c2: removed 12 log segments from log reader
I20260812 06:18:02.512813   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000027 (ops 129-133)
I20260812 06:18:02.512851   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000028 (ops 134-138)
I20260812 06:18:02.512885   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000029 (ops 139-142)
I20260812 06:18:02.512920   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000030 (ops 143-147)
I20260812 06:18:02.512948   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000031 (ops 148-152)
I20260812 06:18:02.512971   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000032 (ops 153-157)
I20260812 06:18:02.513001   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000033 (ops 158-162)
I20260812 06:18:02.513031   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000034 (ops 163-167)
I20260812 06:18:02.513062   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000035 (ops 168-172)
I20260812 06:18:02.513095   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000036 (ops 173-177)
I20260812 06:18:02.513129   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000037 (ops 178-182)
I20260812 06:18:02.513159   743 log.cc:1079] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477484730-625-0/minicluster-data/ts-0-root/wals/b5037e06dd364b308543477444cfa2c2/wal-000000038 (ops 183-187)
I20260812 06:18:02.544687   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: LogGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.032s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:18:02.545193   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:02.570230   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.570765   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2): 462 bytes on disk
I20260812 06:18:02.571244   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: UndoDeltaBlockGCOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.571780   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:02.583151   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.583818   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:02.787997   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.204s	user 0.146s	sys 0.057s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":699,"lbm_read_time_us":14232,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34452,"lbm_writes_lt_1ms":643,"mutex_wait_us":423,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:18:02.788877   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=14.095187
I20260812 06:18:02.844002   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.055s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24275,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.844659   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2): perf score=2.188937
I20260812 06:18:02.860260   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: FlushDeltaMemStoresOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.860760   812 maintenance_manager.cc:419] P c1a6017e2fa145cbafe1d0e3f8608a6a: Scheduling MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2): perf score=1.000000
I20260812 06:18:02.890229   625 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.094s	user 1.901s	sys 0.138s
I20260812 06:18:02.967031   625 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.076s	user 0.003s	sys 0.000s
I20260812 06:18:02.967710   625 tablet_server.cc:179] TabletServer@127.0.156.65:0 shutting down...
I20260812 06:18:03.019632   743 maintenance_manager.cc:643] P c1a6017e2fa145cbafe1d0e3f8608a6a: MajorDeltaCompactionOp(b5037e06dd364b308543477444cfa2c2) complete. Timing: real 0.159s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1274,"lbm_read_time_us":13855,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26387,"lbm_writes_lt_1ms":543,"mutex_wait_us":394,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:03.020469   625 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:03.020933   625 tablet_replica.cc:333] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a: stopping tablet replica
I20260812 06:18:03.021247   625 raft_consensus.cc:2243] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.021557   625 raft_consensus.cc:2272] T b5037e06dd364b308543477444cfa2c2 P c1a6017e2fa145cbafe1d0e3f8608a6a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.039314   625 tablet_server.cc:196] TabletServer@127.0.156.65:0 shutdown complete.
I20260812 06:18:03.067638   625 master.cc:562] Master@127.0.156.126:41957 shutting down...
I20260812 06:18:03.071290   625 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:03.071516   625 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:03.071609   625 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9419d87f0a0f4818b0a55ea50e464f82: stopping tablet replica
I20260812 06:18:03.084041   625 master.cc:584] Master@127.0.156.126:41957 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5681 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:03.189155   625 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.156.126:37849
I20260812 06:18:03.189620   625 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.191972   849 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.192139   625 server_base.cc:1061] running on GCE node
W20260812 06:18:03.191989   845 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.191972   847 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.192468   625 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.192534   625 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.192560   625 hybrid_clock.cc:648] HybridClock initialized: now 1786515483192559 us; error 0 us; skew 500 ppm
I20260812 06:18:03.193398   625 webserver.cc:533] Webserver started at http://127.0.156.126:35921/ using document root <none> and password file <none>
I20260812 06:18:03.193584   625 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.193672   625 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.193761   625 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.194190   625 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/master-0-root/instance:
uuid: "bbf0528fc7f84812ba893d95c0c7d369"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0kls"
I20260812 06:18:03.195735   625 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:03.196713   854 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.196985   625 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.197075   625 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/master-0-root
uuid: "bbf0528fc7f84812ba893d95c0c7d369"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0kls"
I20260812 06:18:03.197167   625 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.213378   625 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.213909   625 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.218117   625 rpc_server.cc:307] RPC server started. Bound to: 127.0.156.126:37849
I20260812 06:18:03.219894   916 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.156.126:37849 every 8 connection(s)
I20260812 06:18:03.220472   917 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.224380   917 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369: Bootstrap starting.
I20260812 06:18:03.225224   917 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.226296   917 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369: No bootstrap required, opened a new log
I20260812 06:18:03.226671   917 raft_consensus.cc:359] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbf0528fc7f84812ba893d95c0c7d369" member_type: VOTER }
I20260812 06:18:03.226763   917 raft_consensus.cc:385] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.226785   917 raft_consensus.cc:740] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bbf0528fc7f84812ba893d95c0c7d369, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.226902   917 consensus_queue.cc:260] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [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: "bbf0528fc7f84812ba893d95c0c7d369" member_type: VOTER }
I20260812 06:18:03.226959   917 raft_consensus.cc:399] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.226981   917 raft_consensus.cc:493] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.227015   917 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.227694   917 raft_consensus.cc:515] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbf0528fc7f84812ba893d95c0c7d369" member_type: VOTER }
I20260812 06:18:03.227813   917 leader_election.cc:304] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [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: bbf0528fc7f84812ba893d95c0c7d369; no voters: 
I20260812 06:18:03.227977   917 leader_election.cc:290] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.228140   920 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.228370   920 raft_consensus.cc:697] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 1 LEADER]: Becoming Leader. State: Replica: bbf0528fc7f84812ba893d95c0c7d369, State: Running, Role: LEADER
I20260812 06:18:03.228487   917 sys_catalog.cc:565] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:03.228541   920 consensus_queue.cc:237] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [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: "bbf0528fc7f84812ba893d95c0c7d369" member_type: VOTER }
I20260812 06:18:03.228968   921 sys_catalog.cc:455] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bbf0528fc7f84812ba893d95c0c7d369" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbf0528fc7f84812ba893d95c0c7d369" member_type: VOTER } }
I20260812 06:18:03.229053   921 sys_catalog.cc:458] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.229310   922 sys_catalog.cc:455] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bbf0528fc7f84812ba893d95c0c7d369. Latest consensus state: current_term: 1 leader_uuid: "bbf0528fc7f84812ba893d95c0c7d369" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbf0528fc7f84812ba893d95c0c7d369" member_type: VOTER } }
I20260812 06:18:03.229382   922 sys_catalog.cc:458] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.229851   925 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:03.230810   925 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:03.231029   625 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:03.232810   925 catalog_manager.cc:1383] Generated new cluster ID: fd529988b0d742fd8a49f66f674adde8
I20260812 06:18:03.232878   925 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:03.238234   925 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:03.238869   925 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:03.246608   925 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369: Generated new TSK 0
I20260812 06:18:03.246863   925 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:03.263548   625 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.265727   941 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.265851   942 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.265820   625 server_base.cc:1061] running on GCE node
W20260812 06:18:03.265985   945 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.266275   625 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.266324   625 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.266345   625 hybrid_clock.cc:648] HybridClock initialized: now 1786515483266344 us; error 0 us; skew 500 ppm
I20260812 06:18:03.267375   625 webserver.cc:533] Webserver started at http://127.0.156.65:45605/ using document root <none> and password file <none>
I20260812 06:18:03.267608   625 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.267670   625 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.267771   625 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.268252   625 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/instance:
uuid: "7f89ad1135a84d5696378bb40b8c0a28"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0kls"
I20260812 06:18:03.270170   625 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:03.271363   950 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.271675   625 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.271771   625 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root
uuid: "7f89ad1135a84d5696378bb40b8c0a28"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-0kls"
I20260812 06:18:03.271872   625 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.291848   625 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.292318   625 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.292701   625 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:03.293210   625 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:03.293272   625 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.293331   625 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:03.293381   625 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.298040   625 rpc_server.cc:307] RPC server started. Bound to: 127.0.156.65:43641
I20260812 06:18:03.299230  1019 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.156.65:43641 every 8 connection(s)
I20260812 06:18:03.308543  1020 heartbeater.cc:344] Connected to a master server at 127.0.156.126:37849
I20260812 06:18:03.308682  1020 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:03.309043  1020 heartbeater.cc:507] Master 127.0.156.126:37849 requested a full tablet report, sending...
I20260812 06:18:03.309974   875 ts_manager.cc:194] Registered new tserver with Master: 7f89ad1135a84d5696378bb40b8c0a28 (127.0.156.65:43641)
I20260812 06:18:03.309984   625 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01122597s
I20260812 06:18:03.310909   875 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48894
I20260812 06:18:03.318696   875 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48904:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:03.328789   982 tablet_service.cc:1511] Processing CreateTablet for tablet 664ef89b76cb48d28cc28041e08a3d71 (DEFAULT_TABLE table=heavy-update-compaction-test [id=161f3453c79f4a05858dc45d6f3d361e]), partition=
I20260812 06:18:03.329118   982 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 664ef89b76cb48d28cc28041e08a3d71. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.331565  1035 tablet_bootstrap.cc:492] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Bootstrap starting.
I20260812 06:18:03.332515  1035 tablet_bootstrap.cc:654] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.333647  1035 tablet_bootstrap.cc:492] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: No bootstrap required, opened a new log
I20260812 06:18:03.333736  1035 ts_tablet_manager.cc:1403] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:03.334236  1035 raft_consensus.cc:359] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f89ad1135a84d5696378bb40b8c0a28" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 43641 } }
I20260812 06:18:03.334372  1035 raft_consensus.cc:385] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.334408  1035 raft_consensus.cc:740] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7f89ad1135a84d5696378bb40b8c0a28, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.334556  1035 consensus_queue.cc:260] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [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: "7f89ad1135a84d5696378bb40b8c0a28" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 43641 } }
I20260812 06:18:03.334656  1035 raft_consensus.cc:399] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.334692  1035 raft_consensus.cc:493] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.334743  1035 raft_consensus.cc:3060] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.335610  1035 raft_consensus.cc:515] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f89ad1135a84d5696378bb40b8c0a28" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 43641 } }
I20260812 06:18:03.335747  1035 leader_election.cc:304] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [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: 7f89ad1135a84d5696378bb40b8c0a28; no voters: 
I20260812 06:18:03.336162  1035 leader_election.cc:290] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.336445  1037 raft_consensus.cc:2804] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.336611  1035 ts_tablet_manager.cc:1434] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:03.336611  1020 heartbeater.cc:499] Master 127.0.156.126:37849 was elected leader, sending a full tablet report...
I20260812 06:18:03.336700  1037 raft_consensus.cc:697] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 1 LEADER]: Becoming Leader. State: Replica: 7f89ad1135a84d5696378bb40b8c0a28, State: Running, Role: LEADER
I20260812 06:18:03.336911  1037 consensus_queue.cc:237] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [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: "7f89ad1135a84d5696378bb40b8c0a28" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 43641 } }
I20260812 06:18:03.338562   875 catalog_manager.cc:5719] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7f89ad1135a84d5696378bb40b8c0a28 (127.0.156.65). New cstate: current_term: 1 leader_uuid: "7f89ad1135a84d5696378bb40b8c0a28" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f89ad1135a84d5696378bb40b8c0a28" member_type: VOTER last_known_addr { host: "127.0.156.65" port: 43641 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:03.399926   625 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.011s	sys 0.012s
I20260812 06:18:03.549705  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71): perf score=19.054940
I20260812 06:18:03.708967   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.159s	user 0.109s	sys 0.045s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":954,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40001,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:03.709733  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling LogGCOp(664ef89b76cb48d28cc28041e08a3d71): free 20743880 bytes of WAL
I20260812 06:18:03.710016   955 log_reader.cc:385] T 664ef89b76cb48d28cc28041e08a3d71: removed 2 log segments from log reader
I20260812 06:18:03.710079   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000001 (ops 1-6)
I20260812 06:18:03.710121   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000002 (ops 7-11)
I20260812 06:18:03.715556   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: LogGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:03.715939  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:03.732831   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.733675  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71): 16411393 bytes on disk
I20260812 06:18:03.734450   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":141,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.735024  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:03.886397   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.151s	user 0.107s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":711,"lbm_read_time_us":12327,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22248,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":339,"threads_started":5,"update_count":2000}
I20260812 06:18:03.887110  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:03.925100   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.038s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16078,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.925645  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:03.942107   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.942737  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:04.075563   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.133s	user 0.101s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1024,"lbm_read_time_us":7989,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24391,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:18:04.076316  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:04.118338   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.042s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16039,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.118848  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:04.129915   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.130651  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:04.252656   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.122s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":770,"lbm_read_time_us":8027,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25147,"lbm_writes_lt_1ms":443,"mutex_wait_us":230,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:18:04.253316  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:04.298774   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.045s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16340,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.299304  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:04.310313   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.311072  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:04.439307   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.128s	user 0.093s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":9595,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25689,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:18:04.439993  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:04.500568   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.060s	user 0.018s	sys 0.029s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17635,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.501178  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:04.513381   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.513985  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:04.676267   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.162s	user 0.109s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":11902,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27764,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:04.677027  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:04.722486   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.045s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19255,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.723050  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:04.734359   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.735379  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:04.868815   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.133s	user 0.087s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":9740,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27127,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:04.869397  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:04.917925   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.048s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.918493  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:04.931404   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.931973  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:04.961359   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1482,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1635,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:04.962114  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling LogGCOp(664ef89b76cb48d28cc28041e08a3d71): free 112239259 bytes of WAL
I20260812 06:18:04.962359   955 log_reader.cc:385] T 664ef89b76cb48d28cc28041e08a3d71: removed 11 log segments from log reader
I20260812 06:18:04.962402   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000003 (ops 12-16)
I20260812 06:18:04.962430   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000004 (ops 17-21)
I20260812 06:18:04.962476   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000005 (ops 22-26)
I20260812 06:18:04.962522   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000006 (ops 27-31)
I20260812 06:18:04.962543   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000007 (ops 32-36)
I20260812 06:18:04.962592   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000008 (ops 37-41)
I20260812 06:18:04.962636   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000009 (ops 42-46)
I20260812 06:18:04.962698   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000010 (ops 47-51)
I20260812 06:18:04.962745   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000011 (ops 52-56)
I20260812 06:18:04.962788   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000012 (ops 57-60)
I20260812 06:18:04.962828   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000013 (ops 61-65)
I20260812 06:18:04.988524   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: LogGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:04.989012  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71): 447 bytes on disk
I20260812 06:18:04.989531   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.990101  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=3.181125
I20260812 06:18:05.003574   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4762,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:05.004046  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:05.014308   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3619,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.014879  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:05.202334   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.187s	user 0.147s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":797,"lbm_read_time_us":13344,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36844,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18688,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:05.203121  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=14.095187
I20260812 06:18:05.251739   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.048s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21265,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.252373  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:05.268544   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.269088  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:05.428804   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.160s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":10196,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32334,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:18:05.429531  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=14.095187
I20260812 06:18:05.475492   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.046s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19654,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.475956  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:05.487175   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.487694  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:05.650866   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.163s	user 0.123s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":12723,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32059,"lbm_writes_lt_1ms":543,"mutex_wait_us":359,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:05.651400  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=11.118625
I20260812 06:18:05.692687   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.041s	user 0.014s	sys 0.022s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19158,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:18:05.693490  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:05.710212   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.016s	user 0.008s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5172,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.710862  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:05.837013   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.126s	user 0.089s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":7911,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24966,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:05.838671  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:05.888841   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18215,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.889443  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:05.900352   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.900825  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:06.065852   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.165s	user 0.113s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":11600,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23565,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.066480  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:06.103076   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.036s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13785,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.103760  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:06.211215   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.107s	user 0.084s	sys 0.022s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":283,"lbm_read_time_us":7814,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19905,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:06.212203  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:06.258704   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.046s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15953,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.259268  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:06.270298   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.271107  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:06.400462   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.129s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1045,"lbm_read_time_us":10927,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22473,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":48896,"update_count":2000}
I20260812 06:18:06.401260  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:06.454448   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.053s	user 0.026s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15885,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.455039  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:06.466226   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.466765  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:06.499480   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.033s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1408,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1487,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:06.500290  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71): 483 bytes on disk
I20260812 06:18:06.500765   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.501436  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:06.645231   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.144s	user 0.089s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":8984,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22622,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:18:06.646013  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling LogGCOp(664ef89b76cb48d28cc28041e08a3d71): free 133024367 bytes of WAL
I20260812 06:18:06.646322   955 log_reader.cc:385] T 664ef89b76cb48d28cc28041e08a3d71: removed 13 log segments from log reader
I20260812 06:18:06.646389   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000014 (ops 66-70)
I20260812 06:18:06.646437   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000015 (ops 71-75)
I20260812 06:18:06.646522   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000016 (ops 76-80)
I20260812 06:18:06.646569   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000017 (ops 81-85)
I20260812 06:18:06.646605   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000018 (ops 86-90)
I20260812 06:18:06.646648   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000019 (ops 91-94)
I20260812 06:18:06.646718   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000020 (ops 95-99)
I20260812 06:18:06.646766   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000021 (ops 100-104)
I20260812 06:18:06.646806   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000022 (ops 105-109)
I20260812 06:18:06.646849   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000023 (ops 110-114)
I20260812 06:18:06.646891   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000024 (ops 115-119)
I20260812 06:18:06.646934   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000025 (ops 120-124)
I20260812 06:18:06.646974   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000026 (ops 125-129)
I20260812 06:18:06.679494   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: LogGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.033s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:06.680473  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=17.071750
I20260812 06:18:06.732685   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.052s	user 0.029s	sys 0.020s Metrics: {"bytes_written":18748277,"delete_count":0,"lbm_write_time_us":23555,"lbm_writes_lt_1ms":460,"reinsert_count":0,"update_count":2285}
I20260812 06:18:06.733237  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=4.173312
I20260812 06:18:06.758015   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.025s	user 0.023s	sys 0.000s Metrics: {"bytes_written":5866711,"delete_count":0,"lbm_write_time_us":8920,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:18:06.758699  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:06.966212   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.207s	user 0.138s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877110,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1353,"lbm_read_time_us":14484,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36711,"lbm_writes_lt_1ms":643,"mutex_wait_us":476,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":3000}
I20260812 06:18:06.966841  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=14.095187
I20260812 06:18:07.027262   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.060s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20408,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.027931  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:07.039417   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.039925  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:07.221539   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.181s	user 0.139s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1205,"lbm_read_time_us":12147,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29225,"lbm_writes_lt_1ms":543,"mutex_wait_us":363,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:07.222128  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=14.095187
I20260812 06:18:07.281275   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.059s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23493,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.281921  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:07.293429   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.294040  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:07.503355   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.209s	user 0.124s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":567,"lbm_read_time_us":11627,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33678,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:07.503998  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=14.095187
I20260812 06:18:07.556315   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.052s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21641,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.556814  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:07.568297   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.568789  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:07.735736   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.167s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1082,"lbm_read_time_us":9596,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31871,"lbm_writes_lt_1ms":543,"mutex_wait_us":405,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:18:07.736618  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=11.118625
I20260812 06:18:07.769218   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.032s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14277,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:07.770125  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:07.788578   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.018s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.789134  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:07.914355   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.125s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":45,"lbm_read_time_us":7723,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24560,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:07.915021  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=10.126437
I20260812 06:18:07.954700   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.040s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15687,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.955361  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:07.966799   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.967525  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:07.995693   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushMRSOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.028s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1678,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:07.996413  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling LogGCOp(664ef89b76cb48d28cc28041e08a3d71): free 112692675 bytes of WAL
I20260812 06:18:07.996665   955 log_reader.cc:385] T 664ef89b76cb48d28cc28041e08a3d71: removed 11 log segments from log reader
I20260812 06:18:07.996730   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000027 (ops 130-134)
I20260812 06:18:07.996785   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000028 (ops 135-139)
I20260812 06:18:07.996846   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000029 (ops 140-144)
I20260812 06:18:07.996891   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000030 (ops 145-149)
I20260812 06:18:07.996932   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000031 (ops 150-154)
I20260812 06:18:07.996971   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000032 (ops 155-159)
I20260812 06:18:07.997009   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000033 (ops 160-164)
I20260812 06:18:07.997046   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000034 (ops 165-169)
I20260812 06:18:07.997085   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000035 (ops 170-174)
I20260812 06:18:07.997124   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000036 (ops 175-179)
I20260812 06:18:07.997164   955 log.cc:1079] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: Deleting log segment in path: /tmp/dist-test-taskD7K9jN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477484730-625-0/minicluster-data/ts-0-root/wals/664ef89b76cb48d28cc28041e08a3d71/wal-000000037 (ops 180-184)
I20260812 06:18:08.025776   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: LogGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:08.026298  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71): 461 bytes on disk
I20260812 06:18:08.026765   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: UndoDeltaBlockGCOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.027393  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:08.044866   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.045346  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:08.056671   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.057354  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:08.232969   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.175s	user 0.141s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":187,"lbm_read_time_us":12822,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37370,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28160,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:08.233809  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=14.095187
I20260812 06:18:08.289448   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.055s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22976,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.290061  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71): perf score=2.188937
I20260812 06:18:08.301036   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: FlushDeltaMemStoresOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.301597  1021 maintenance_manager.cc:419] P 7f89ad1135a84d5696378bb40b8c0a28: Scheduling MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71): perf score=1.000000
I20260812 06:18:08.336580   625 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.937s	user 1.782s	sys 0.176s
I20260812 06:18:08.390486   625 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.002s	sys 0.000s
I20260812 06:18:08.391053   625 tablet_server.cc:179] TabletServer@127.0.156.65:0 shutting down...
I20260812 06:18:08.443440   955 maintenance_manager.cc:643] P 7f89ad1135a84d5696378bb40b8c0a28: MajorDeltaCompactionOp(664ef89b76cb48d28cc28041e08a3d71) complete. Timing: real 0.142s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":672,"lbm_read_time_us":12939,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26570,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:18:08.444197   625 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:08.444759   625 tablet_replica.cc:333] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28: stopping tablet replica
I20260812 06:18:08.444942   625 raft_consensus.cc:2243] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.445147   625 raft_consensus.cc:2272] T 664ef89b76cb48d28cc28041e08a3d71 P 7f89ad1135a84d5696378bb40b8c0a28 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.461935   625 tablet_server.cc:196] TabletServer@127.0.156.65:0 shutdown complete.
I20260812 06:18:08.489639   625 master.cc:562] Master@127.0.156.126:37849 shutting down...
I20260812 06:18:08.493422   625 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.493671   625 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.493786   625 tablet_replica.cc:333] T 00000000000000000000000000000000 P bbf0528fc7f84812ba893d95c0c7d369: stopping tablet replica
I20260812 06:18:08.506651   625 master.cc:584] Master@127.0.156.126:37849 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5424 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11106 ms total)

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