[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:20:15.435062   676 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.169.62:40397
I20260812 06:20:15.436074   676 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:20:15.436681   676 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:15.443152   686 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:15.443212   685 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:15.443428   689 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:15.443528   676 server_base.cc:1061] running on GCE node
I20260812 06:20:15.444002   676 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.444108   676 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:15.444133   676 hybrid_clock.cc:648] HybridClock initialized: now 1786515615444132 us; error 0 us; skew 500 ppm
I20260812 06:20:15.445955   676 webserver.cc:533] Webserver started at http://127.0.169.62:39187/ using document root <none> and password file <none>
I20260812 06:20:15.446542   676 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.446605   676 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.446790   676 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.448375   676 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/master-0-root/instance:
uuid: "444258e02dda40b199d13139917ae1b0"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-jztv"
I20260812 06:20:15.451819   676 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:15.453931   698 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.455003   676 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:15.455142   676 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/master-0-root
uuid: "444258e02dda40b199d13139917ae1b0"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-jztv"
I20260812 06:20:15.455251   676 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:15.474370   676 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.475044   676 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:20:15.475230   676 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.483235   676 rpc_server.cc:307] RPC server started. Bound to: 127.0.169.62:40397
I20260812 06:20:15.483248   786 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.169.62:40397 every 8 connection(s)
I20260812 06:20:15.485498   788 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:15.490998   788 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0: Bootstrap starting.
I20260812 06:20:15.493462   788 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.494547   788 log.cc:826] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:15.496318   788 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0: No bootstrap required, opened a new log
I20260812 06:20:15.499285   788 raft_consensus.cc:359] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "444258e02dda40b199d13139917ae1b0" member_type: VOTER }
I20260812 06:20:15.499514   788 raft_consensus.cc:385] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.499600   788 raft_consensus.cc:740] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 444258e02dda40b199d13139917ae1b0, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.500217   788 consensus_queue.cc:260] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [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: "444258e02dda40b199d13139917ae1b0" member_type: VOTER }
I20260812 06:20:15.500442   788 raft_consensus.cc:399] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.500519   788 raft_consensus.cc:493] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.500702   788 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.501503   788 raft_consensus.cc:515] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "444258e02dda40b199d13139917ae1b0" member_type: VOTER }
I20260812 06:20:15.501955   788 leader_election.cc:304] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [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: 444258e02dda40b199d13139917ae1b0; no voters: 
I20260812 06:20:15.502401   788 leader_election.cc:290] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.502537   795 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.502810   795 raft_consensus.cc:697] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 1 LEADER]: Becoming Leader. State: Replica: 444258e02dda40b199d13139917ae1b0, State: Running, Role: LEADER
I20260812 06:20:15.503219   795 consensus_queue.cc:237] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [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: "444258e02dda40b199d13139917ae1b0" member_type: VOTER }
I20260812 06:20:15.503494   788 sys_catalog.cc:565] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:15.505410   797 sys_catalog.cc:455] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 444258e02dda40b199d13139917ae1b0. Latest consensus state: current_term: 1 leader_uuid: "444258e02dda40b199d13139917ae1b0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "444258e02dda40b199d13139917ae1b0" member_type: VOTER } }
I20260812 06:20:15.505415   796 sys_catalog.cc:455] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "444258e02dda40b199d13139917ae1b0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "444258e02dda40b199d13139917ae1b0" member_type: VOTER } }
I20260812 06:20:15.505563   797 sys_catalog.cc:458] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.505563   796 sys_catalog.cc:458] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.505843   676 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:15.506011   815 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:15.508170   815 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:15.512542   815 catalog_manager.cc:1383] Generated new cluster ID: f9905335696440888ec7b3194f194f3e
I20260812 06:20:15.512607   815 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:15.528784   815 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:15.529959   815 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:15.537971   815 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0: Generated new TSK 0
I20260812 06:20:15.538776   815 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:15.570915   676 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:15.574275   676 server_base.cc:1061] running on GCE node
W20260812 06:20:15.574203   821 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:15.574195   825 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:15.574427   822 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:15.574704   676 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.574747   676 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:15.574764   676 hybrid_clock.cc:648] HybridClock initialized: now 1786515615574764 us; error 0 us; skew 500 ppm
I20260812 06:20:15.575731   676 webserver.cc:533] Webserver started at http://127.0.169.1:35027/ using document root <none> and password file <none>
I20260812 06:20:15.575930   676 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.576009   676 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.576095   676 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.576519   676 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/instance:
uuid: "6778bb84f6c546fdbac37d9aeb0e68cf"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-jztv"
I20260812 06:20:15.578120   676 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:15.579226   832 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.579531   676 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:15.579625   676 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root
uuid: "6778bb84f6c546fdbac37d9aeb0e68cf"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-jztv"
I20260812 06:20:15.579716   676 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:15.592463   676 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.592952   676 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.593503   676 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:15.594453   676 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:15.594529   676 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.594605   676 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:15.594657   676 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.601784   676 rpc_server.cc:307] RPC server started. Bound to: 127.0.169.1:36915
I20260812 06:20:15.601811   942 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.169.1:36915 every 8 connection(s)
I20260812 06:20:15.615120   943 heartbeater.cc:344] Connected to a master server at 127.0.169.62:40397
I20260812 06:20:15.615386   943 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:15.615859   943 heartbeater.cc:507] Master 127.0.169.62:40397 requested a full tablet report, sending...
I20260812 06:20:15.617272   720 ts_manager.cc:194] Registered new tserver with Master: 6778bb84f6c546fdbac37d9aeb0e68cf (127.0.169.1:36915)
I20260812 06:20:15.617375   676 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014828853s
I20260812 06:20:15.618597   720 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36968
I20260812 06:20:15.627080   720 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36972:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:15.641669   878 tablet_service.cc:1511] Processing CreateTablet for tablet 05ce0f12c1c84e22946612c671e5884b (DEFAULT_TABLE table=heavy-update-compaction-test [id=dcda7d6e2aa14cf6b632b99c735f80ce]), partition=
I20260812 06:20:15.642143   878 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 05ce0f12c1c84e22946612c671e5884b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:15.644398   963 tablet_bootstrap.cc:492] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Bootstrap starting.
I20260812 06:20:15.645951   963 tablet_bootstrap.cc:654] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.647328   963 tablet_bootstrap.cc:492] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: No bootstrap required, opened a new log
I20260812 06:20:15.647447   963 ts_tablet_manager.cc:1403] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:20:15.647964   963 raft_consensus.cc:359] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6778bb84f6c546fdbac37d9aeb0e68cf" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 36915 } }
I20260812 06:20:15.648098   963 raft_consensus.cc:385] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.648135   963 raft_consensus.cc:740] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6778bb84f6c546fdbac37d9aeb0e68cf, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.648331   963 consensus_queue.cc:260] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [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: "6778bb84f6c546fdbac37d9aeb0e68cf" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 36915 } }
I20260812 06:20:15.648487   963 raft_consensus.cc:399] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.648530   963 raft_consensus.cc:493] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.648572   963 raft_consensus.cc:3060] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.649652   963 raft_consensus.cc:515] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6778bb84f6c546fdbac37d9aeb0e68cf" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 36915 } }
I20260812 06:20:15.649808   963 leader_election.cc:304] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [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: 6778bb84f6c546fdbac37d9aeb0e68cf; no voters: 
I20260812 06:20:15.650028   963 leader_election.cc:290] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.650149   966 raft_consensus.cc:2804] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.650383   963 ts_tablet_manager.cc:1434] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:20:15.650431   966 raft_consensus.cc:697] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 1 LEADER]: Becoming Leader. State: Replica: 6778bb84f6c546fdbac37d9aeb0e68cf, State: Running, Role: LEADER
I20260812 06:20:15.650650   966 consensus_queue.cc:237] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [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: "6778bb84f6c546fdbac37d9aeb0e68cf" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 36915 } }
I20260812 06:20:15.650671   943 heartbeater.cc:499] Master 127.0.169.62:40397 was elected leader, sending a full tablet report...
I20260812 06:20:15.653496   720 catalog_manager.cc:5719] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf reported cstate change: term changed from 0 to 1, leader changed from <none> to 6778bb84f6c546fdbac37d9aeb0e68cf (127.0.169.1). New cstate: current_term: 1 leader_uuid: "6778bb84f6c546fdbac37d9aeb0e68cf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6778bb84f6c546fdbac37d9aeb0e68cf" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 36915 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:15.724022   676 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.027s	sys 0.003s
I20260812 06:20:15.853106   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushMRSOp(05ce0f12c1c84e22946612c671e5884b): perf score=19.054940
I20260812 06:20:16.034122   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushMRSOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.181s	user 0.137s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":220,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":979,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44629,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":159,"threads_started":1,"update_count":1500}
I20260812 06:20:16.035517   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling LogGCOp(05ce0f12c1c84e22946612c671e5884b): free 20743880 bytes of WAL
I20260812 06:20:16.036031   839 log_reader.cc:385] T 05ce0f12c1c84e22946612c671e5884b: removed 2 log segments from log reader
I20260812 06:20:16.036229   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000001 (ops 1-6)
I20260812 06:20:16.036448   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000002 (ops 7-11)
I20260812 06:20:16.042294   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: LogGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:20:16.042676   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=3.181125
I20260812 06:20:16.068583   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.026s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:16.069103   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b): 16411393 bytes on disk
I20260812 06:20:16.069833   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b) 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:20:16.070384   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:16.085095   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5334,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.085745   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:16.262907   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.177s	user 0.098s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":962,"lbm_read_time_us":13997,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27848,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":315,"threads_started":5,"update_count":2500}
I20260812 06:20:16.263631   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:16.315236   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.051s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15833,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.315785   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:16.329000   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.329742   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:16.451058   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.121s	user 0.089s	sys 0.032s 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":157,"lbm_read_time_us":8680,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22795,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:16.451692   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:16.497552   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.046s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16739,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.498028   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:16.508939   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.509377   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:16.633859   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.124s	user 0.096s	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":281,"lbm_read_time_us":8180,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23299,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:20:16.634591   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:16.667690   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.033s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14074,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.668243   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:16.796391   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.128s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":901,"lbm_read_time_us":9330,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23308,"lbm_writes_lt_1ms":343,"mutex_wait_us":331,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.797125   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:16.834620   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.037s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16122,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.835122   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:16.850513   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.851207   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:16.981949   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.131s	user 0.102s	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":635,"lbm_read_time_us":9368,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24719,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:20:16.982571   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:17.026464   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.044s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":16320,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.027019   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:17.041891   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.042455   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:17.159771   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.117s	user 0.095s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":8465,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21593,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:17.162490   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:17.199692   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.037s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16260,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.200400   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:17.218376   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.218982   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushMRSOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:17.267272   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushMRSOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.048s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1503,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1946,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:17.268139   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling LogGCOp(05ce0f12c1c84e22946612c671e5884b): free 111786256 bytes of WAL
I20260812 06:20:17.268404   839 log_reader.cc:385] T 05ce0f12c1c84e22946612c671e5884b: removed 11 log segments from log reader
I20260812 06:20:17.268465   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000003 (ops 12-16)
I20260812 06:20:17.268503   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000004 (ops 17-21)
I20260812 06:20:17.268532   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000005 (ops 22-26)
I20260812 06:20:17.268560   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000006 (ops 27-31)
I20260812 06:20:17.268591   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000007 (ops 32-36)
I20260812 06:20:17.268625   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000008 (ops 37-40)
I20260812 06:20:17.268652   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000009 (ops 41-45)
I20260812 06:20:17.268682   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000010 (ops 46-50)
I20260812 06:20:17.268711   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000011 (ops 51-54)
I20260812 06:20:17.268738   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000012 (ops 55-59)
I20260812 06:20:17.268770   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000013 (ops 60-64)
I20260812 06:20:17.293941   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: LogGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:17.294477   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b): 462 bytes on disk
I20260812 06:20:17.295004   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.295519   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=6.157687
I20260812 06:20:17.319216   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.024s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":9933,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:17.319734   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling LogGCOp(05ce0f12c1c84e22946612c671e5884b): free 8767067 bytes of WAL
I20260812 06:20:17.319947   839 log_reader.cc:385] T 05ce0f12c1c84e22946612c671e5884b: removed 1 log segments from log reader
I20260812 06:20:17.319994   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000014 (ops 65-69)
I20260812 06:20:17.321696   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: LogGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:17.322005   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:17.334059   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.334672   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:17.536634   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.202s	user 0.151s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":266,"lbm_read_time_us":11933,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40410,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:20:17.537246   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:17.576586   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17499,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.577117   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:17.590637   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.591087   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:17.754379   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.163s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1333,"lbm_read_time_us":10631,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28909,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:20:17.755172   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:17.801586   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.046s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19423,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.802304   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:17.950963   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.148s	user 0.113s	sys 0.033s 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":673,"lbm_read_time_us":7245,"lbm_reads_lt_1ms":363,"lbm_write_time_us":25637,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":330,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":1500}
I20260812 06:20:17.951653   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:18.002156   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.050s	user 0.030s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21171,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.002846   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.034904   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.032s	user 0.020s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9244,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.035599   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.052596   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.017s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.053048   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:18.217308   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.164s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":638,"lbm_read_time_us":10025,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31527,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":620160,"update_count":2500}
I20260812 06:20:18.217804   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:18.273067   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.055s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.273595   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.286417   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.286998   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:18.427527   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.140s	user 0.108s	sys 0.032s 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":297,"lbm_read_time_us":8743,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30242,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:20:18.430651   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:18.461643   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13446,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.462205   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.478534   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.479540   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:18.602532   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.123s	user 0.099s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":79,"lbm_read_time_us":10311,"lbm_reads_lt_1ms":468,"lbm_write_time_us":20898,"lbm_writes_lt_1ms":443,"mutex_wait_us":18,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:20:18.603193   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=10.126437
I20260812 06:20:18.650127   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.047s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16810,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":1500}
I20260812 06:20:18.650697   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.661142   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.661586   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushMRSOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:18.701802   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushMRSOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.040s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":132,"dirs.run_wall_time_us":1304,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2050,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:18.702620   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling LogGCOp(05ce0f12c1c84e22946612c671e5884b): free 111786315 bytes of WAL
I20260812 06:20:18.702840   839 log_reader.cc:385] T 05ce0f12c1c84e22946612c671e5884b: removed 11 log segments from log reader
I20260812 06:20:18.702900   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000015 (ops 70-74)
I20260812 06:20:18.702952   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000016 (ops 75-79)
I20260812 06:20:18.703019   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000017 (ops 80-84)
I20260812 06:20:18.703061   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000018 (ops 85-89)
I20260812 06:20:18.703095   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000019 (ops 90-94)
I20260812 06:20:18.703133   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000020 (ops 95-98)
I20260812 06:20:18.703169   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000021 (ops 99-103)
I20260812 06:20:18.703205   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000022 (ops 104-108)
I20260812 06:20:18.703241   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000023 (ops 109-113)
I20260812 06:20:18.703279   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000024 (ops 114-118)
I20260812 06:20:18.703316   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000025 (ops 119-122)
I20260812 06:20:18.725289   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: LogGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:20:18.725692   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.747581   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.748080   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:18.758370   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.010s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.759034   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b): 446 bytes on disk
I20260812 06:20:18.759639   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.760191   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:18.953276   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.193s	user 0.128s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2155,"lbm_read_time_us":12529,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32115,"lbm_writes_lt_1ms":643,"mutex_wait_us":872,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:20:18.954032   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:18.998697   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.044s	user 0.035s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19226,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.999284   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.019635   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.020s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.020241   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:19.193042   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.173s	user 0.125s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":500,"lbm_read_time_us":11698,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30382,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:20:19.193610   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:19.250638   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.057s	user 0.045s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18879,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.251153   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.267910   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.268464   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:19.430104   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.161s	user 0.091s	sys 0.069s 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":496,"lbm_read_time_us":11959,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27929,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:20:19.430840   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=11.118625
I20260812 06:20:19.465412   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.034s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14454,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.466059   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.496035   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.030s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6423,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.496506   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.507434   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.507915   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:19.672734   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.165s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":364,"lbm_read_time_us":11536,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27467,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:19.673408   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:19.729053   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.055s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21712,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.729609   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.741274   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.741736   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:19.913159   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.171s	user 0.127s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":11949,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29952,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:20:19.913751   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=11.118625
I20260812 06:20:19.952364   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.038s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14732,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.953033   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.973405   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.973863   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:19.983865   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.984356   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:20.168836   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.184s	user 0.117s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":383,"lbm_read_time_us":11671,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29556,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32256,"update_count":2500}
I20260812 06:20:20.169399   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:20.217278   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.048s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19179,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.217804   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:20.229595   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.230307   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushMRSOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:20.262828   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushMRSOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1500,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1623,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:20.263549   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling LogGCOp(05ce0f12c1c84e22946612c671e5884b): free 129320697 bytes of WAL
I20260812 06:20:20.263774   839 log_reader.cc:385] T 05ce0f12c1c84e22946612c671e5884b: removed 13 log segments from log reader
I20260812 06:20:20.263819   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000026 (ops 123-127)
I20260812 06:20:20.263847   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000027 (ops 128-132)
I20260812 06:20:20.263906   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000028 (ops 133-137)
I20260812 06:20:20.263952   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000029 (ops 138-142)
I20260812 06:20:20.264002   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000030 (ops 143-147)
I20260812 06:20:20.264024   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000031 (ops 148-152)
I20260812 06:20:20.264078   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000032 (ops 153-157)
I20260812 06:20:20.264108   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000033 (ops 158-162)
I20260812 06:20:20.264147   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000034 (ops 163-166)
I20260812 06:20:20.264184   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000035 (ops 167-171)
I20260812 06:20:20.264221   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000036 (ops 172-176)
I20260812 06:20:20.264256   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000037 (ops 177-180)
I20260812 06:20:20.264285   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000038 (ops 181-185)
I20260812 06:20:20.293170   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: LogGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:20.293561   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b): 492 bytes on disk
I20260812 06:20:20.293984   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: UndoDeltaBlockGCOp(05ce0f12c1c84e22946612c671e5884b) 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:20:20.294688   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=3.181125
I20260812 06:20:20.307271   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4759046,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 06:20:20.307750   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling LogGCOp(05ce0f12c1c84e22946612c671e5884b): free 12018004 bytes of WAL
I20260812 06:20:20.307993   839 log_reader.cc:385] T 05ce0f12c1c84e22946612c671e5884b: removed 1 log segments from log reader
I20260812 06:20:20.308053   839 log.cc:1079] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615424532-676-0/minicluster-data/ts-0-root/wals/05ce0f12c1c84e22946612c671e5884b/wal-000000039 (ops 186-190)
I20260812 06:20:20.310968   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: LogGCOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:20.311311   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:20.325006   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4766,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:20:20.325681   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:20.548020   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.222s	user 0.131s	sys 0.091s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":529,"lbm_read_time_us":15743,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38429,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:20:20.552464   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=14.095187
I20260812 06:20:20.581601   676 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.857s	user 1.796s	sys 0.144s
I20260812 06:20:20.600066   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.047s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20141,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:20.600628   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b): perf score=2.188937
I20260812 06:20:20.610688   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: FlushDeltaMemStoresOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.611124   944 maintenance_manager.cc:419] P 6778bb84f6c546fdbac37d9aeb0e68cf: Scheduling MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b): perf score=1.000000
I20260812 06:20:20.629535   676 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.047s	user 0.002s	sys 0.000s
I20260812 06:20:20.630331   676 tablet_server.cc:179] TabletServer@127.0.169.1:0 shutting down...
I20260812 06:20:20.751149   839 maintenance_manager.cc:643] P 6778bb84f6c546fdbac37d9aeb0e68cf: MajorDeltaCompactionOp(05ce0f12c1c84e22946612c671e5884b) complete. Timing: real 0.140s	user 0.084s	sys 0.056s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512301,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":8709,"lbm_reads_lt_1ms":518,"lbm_write_time_us":23717,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":48768,"update_count":2500}
I20260812 06:20:20.752008   676 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:20.752470   676 tablet_replica.cc:333] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf: stopping tablet replica
I20260812 06:20:20.752709   676 raft_consensus.cc:2243] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:20.752949   676 raft_consensus.cc:2272] T 05ce0f12c1c84e22946612c671e5884b P 6778bb84f6c546fdbac37d9aeb0e68cf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:20.758560   676 tablet_server.cc:196] TabletServer@127.0.169.1:0 shutdown complete.
I20260812 06:20:20.796085   676 master.cc:562] Master@127.0.169.62:40397 shutting down...
I20260812 06:20:20.800292   676 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:20.800468   676 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:20.800530   676 tablet_replica.cc:333] T 00000000000000000000000000000000 P 444258e02dda40b199d13139917ae1b0: stopping tablet replica
I20260812 06:20:20.813788   676 master.cc:584] Master@127.0.169.62:40397 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5465 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:20.899909   676 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.169.62:40481
I20260812 06:20:20.900250   676 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:20.902379   990 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:20.902423   676 server_base.cc:1061] running on GCE node
W20260812 06:20:20.902372   995 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:20.902372   992 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:20.902854   676 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:20.902897   676 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:20.902920   676 hybrid_clock.cc:648] HybridClock initialized: now 1786515620902920 us; error 0 us; skew 500 ppm
I20260812 06:20:20.903738   676 webserver.cc:533] Webserver started at http://127.0.169.62:32987/ using document root <none> and password file <none>
I20260812 06:20:20.903908   676 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:20.903962   676 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:20.904062   676 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:20.904465   676 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/master-0-root/instance:
uuid: "e5554953d9bc484ab8276aea43a7b00f"
format_stamp: "Formatted at 2026-08-12 06:20:20 on dist-test-slave-jztv"
I20260812 06:20:20.905979   676 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:20.906955  1002 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:20.907217   676 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:20.907279   676 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/master-0-root
uuid: "e5554953d9bc484ab8276aea43a7b00f"
format_stamp: "Formatted at 2026-08-12 06:20:20 on dist-test-slave-jztv"
I20260812 06:20:20.907364   676 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:20.931167   676 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:20.931581   676 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:20.935894   676 rpc_server.cc:307] RPC server started. Bound to: 127.0.169.62:40481
I20260812 06:20:20.937768  1081 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.169.62:40481 every 8 connection(s)
I20260812 06:20:20.941912  1082 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:20.951102  1082 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f: Bootstrap starting.
I20260812 06:20:20.951922  1082 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:20.952944  1082 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f: No bootstrap required, opened a new log
I20260812 06:20:20.953341  1082 raft_consensus.cc:359] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5554953d9bc484ab8276aea43a7b00f" member_type: VOTER }
I20260812 06:20:20.953425  1082 raft_consensus.cc:385] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:20.953480  1082 raft_consensus.cc:740] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e5554953d9bc484ab8276aea43a7b00f, State: Initialized, Role: FOLLOWER
I20260812 06:20:20.953655  1082 consensus_queue.cc:260] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [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: "e5554953d9bc484ab8276aea43a7b00f" member_type: VOTER }
I20260812 06:20:20.953729  1082 raft_consensus.cc:399] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:20.953788  1082 raft_consensus.cc:493] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:20.953850  1082 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:20.954617  1082 raft_consensus.cc:515] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5554953d9bc484ab8276aea43a7b00f" member_type: VOTER }
I20260812 06:20:20.954768  1082 leader_election.cc:304] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [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: e5554953d9bc484ab8276aea43a7b00f; no voters: 
I20260812 06:20:20.954972  1082 leader_election.cc:290] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:20.955106  1086 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:20.955305  1086 raft_consensus.cc:697] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 1 LEADER]: Becoming Leader. State: Replica: e5554953d9bc484ab8276aea43a7b00f, State: Running, Role: LEADER
I20260812 06:20:20.955421  1082 sys_catalog.cc:565] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:20.955502  1086 consensus_queue.cc:237] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [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: "e5554953d9bc484ab8276aea43a7b00f" member_type: VOTER }
I20260812 06:20:20.955964  1087 sys_catalog.cc:455] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e5554953d9bc484ab8276aea43a7b00f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5554953d9bc484ab8276aea43a7b00f" member_type: VOTER } }
I20260812 06:20:20.956015  1088 sys_catalog.cc:455] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [sys.catalog]: SysCatalogTable state changed. Reason: New leader e5554953d9bc484ab8276aea43a7b00f. Latest consensus state: current_term: 1 leader_uuid: "e5554953d9bc484ab8276aea43a7b00f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5554953d9bc484ab8276aea43a7b00f" member_type: VOTER } }
I20260812 06:20:20.956067  1087 sys_catalog.cc:458] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:20.956101  1088 sys_catalog.cc:458] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:20.956401  1094 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:20.957453  1094 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:20.957666   676 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:20.959302  1094 catalog_manager.cc:1383] Generated new cluster ID: 5eed09b81e2d41db8b3eeceaf9a433d6
I20260812 06:20:20.959373  1094 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:20.981405  1094 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:20.981949  1094 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:20.990146  1094 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f: Generated new TSK 0
I20260812 06:20:20.990338  1094 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:21.022642   676 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.024885  1109 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:21.025005   676 server_base.cc:1061] running on GCE node
W20260812 06:20:21.025020  1110 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:21.025106  1114 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:21.025357   676 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.025425   676 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:21.025461   676 hybrid_clock.cc:648] HybridClock initialized: now 1786515621025461 us; error 0 us; skew 500 ppm
I20260812 06:20:21.026437   676 webserver.cc:533] Webserver started at http://127.0.169.1:43581/ using document root <none> and password file <none>
I20260812 06:20:21.026633   676 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.026711   676 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.026818   676 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.027240   676 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/instance:
uuid: "20a6684b08ff460492d6d4577999b662"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-jztv"
I20260812 06:20:21.028785   676 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:21.029677  1127 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.029934   676 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:21.030026   676 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root
uuid: "20a6684b08ff460492d6d4577999b662"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-jztv"
I20260812 06:20:21.030114   676 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:21.036692   676 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.037043   676 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.037340   676 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:21.037799   676 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:21.037860   676 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.037920   676 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:21.037956   676 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.042191   676 rpc_server.cc:307] RPC server started. Bound to: 127.0.169.1:37145
I20260812 06:20:21.042284  1236 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.169.1:37145 every 8 connection(s)
I20260812 06:20:21.051012  1238 heartbeater.cc:344] Connected to a master server at 127.0.169.62:40481
I20260812 06:20:21.051133  1238 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:21.051364  1238 heartbeater.cc:507] Master 127.0.169.62:40481 requested a full tablet report, sending...
I20260812 06:20:21.052021  1025 ts_manager.cc:194] Registered new tserver with Master: 20a6684b08ff460492d6d4577999b662 (127.0.169.1:37145)
I20260812 06:20:21.052701   676 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009960052s
I20260812 06:20:21.052875  1025 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38994
I20260812 06:20:21.059744  1025 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39000:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:21.068463  1180 tablet_service.cc:1511] Processing CreateTablet for tablet 7184c7f37b1a4ced99cf01975984fbb2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d98f7c5a375d4bc5bbab62c00d35a3e1]), partition=
I20260812 06:20:21.068761  1180 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7184c7f37b1a4ced99cf01975984fbb2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:21.070851  1255 tablet_bootstrap.cc:492] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Bootstrap starting.
I20260812 06:20:21.071681  1255 tablet_bootstrap.cc:654] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.072849  1255 tablet_bootstrap.cc:492] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: No bootstrap required, opened a new log
I20260812 06:20:21.072937  1255 ts_tablet_manager.cc:1403] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:21.073515  1255 raft_consensus.cc:359] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20a6684b08ff460492d6d4577999b662" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 37145 } }
I20260812 06:20:21.073635  1255 raft_consensus.cc:385] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.073660  1255 raft_consensus.cc:740] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 20a6684b08ff460492d6d4577999b662, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.073843  1255 consensus_queue.cc:260] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [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: "20a6684b08ff460492d6d4577999b662" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 37145 } }
I20260812 06:20:21.073958  1255 raft_consensus.cc:399] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.074018  1255 raft_consensus.cc:493] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.074075  1255 raft_consensus.cc:3060] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.074858  1255 raft_consensus.cc:515] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20a6684b08ff460492d6d4577999b662" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 37145 } }
I20260812 06:20:21.075021  1255 leader_election.cc:304] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [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: 20a6684b08ff460492d6d4577999b662; no voters: 
I20260812 06:20:21.075240  1255 leader_election.cc:290] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.075364  1258 raft_consensus.cc:2804] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.075613  1255 ts_tablet_manager.cc:1434] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:20:21.075630  1258 raft_consensus.cc:697] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 1 LEADER]: Becoming Leader. State: Replica: 20a6684b08ff460492d6d4577999b662, State: Running, Role: LEADER
I20260812 06:20:21.075662  1238 heartbeater.cc:499] Master 127.0.169.62:40481 was elected leader, sending a full tablet report...
I20260812 06:20:21.075805  1258 consensus_queue.cc:237] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [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: "20a6684b08ff460492d6d4577999b662" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 37145 } }
I20260812 06:20:21.077114  1025 catalog_manager.cc:5719] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 reported cstate change: term changed from 0 to 1, leader changed from <none> to 20a6684b08ff460492d6d4577999b662 (127.0.169.1). New cstate: current_term: 1 leader_uuid: "20a6684b08ff460492d6d4577999b662" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20a6684b08ff460492d6d4577999b662" member_type: VOTER last_known_addr { host: "127.0.169.1" port: 37145 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:21.135001   676 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.013s	sys 0.009s
I20260812 06:20:21.293169  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=19.054940
I20260812 06:20:21.458843  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.165s	user 0.121s	sys 0.043s Metrics: {"bytes_written":13086951,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":925,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44541,"lbm_writes_lt_1ms":776,"mutex_wait_us":221,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1595}
I20260812 06:20:21.459542  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling LogGCOp(7184c7f37b1a4ced99cf01975984fbb2): free 20290830 bytes of WAL
I20260812 06:20:21.459785  1135 log_reader.cc:385] T 7184c7f37b1a4ced99cf01975984fbb2: removed 2 log segments from log reader
I20260812 06:20:21.459851  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000001 (ops 1-6)
I20260812 06:20:21.459903  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000002 (ops 7-10)
I20260812 06:20:21.464061  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: LogGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:21.464443  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:21.478579  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3733435,"delete_count":0,"lbm_write_time_us":3639,"lbm_writes_lt_1ms":94,"mutex_wait_us":1,"reinsert_count":0,"update_count":455}
I20260812 06:20:21.479065  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:21.492213  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4928,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.492794  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2): 16411391 bytes on disk
I20260812 06:20:21.493309  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2) 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:20:21.493747  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:21.670600  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.177s	user 0.114s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774791,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":969,"lbm_read_time_us":11572,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27349,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":383,"threads_started":5,"update_count":2500}
I20260812 06:20:21.671345  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:21.722568  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.051s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.723083  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:21.735098  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.735756  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:21.882627  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.147s	user 0.099s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":9335,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29530,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:20:21.883267  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=11.118625
I20260812 06:20:21.918167  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.035s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15127,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.918774  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:21.932242  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5014,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.932793  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:22.053215  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.120s	user 0.096s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":7958,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23357,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:20:22.053920  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=10.126437
I20260812 06:20:22.097625  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.042s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17555,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.098147  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:22.108536  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.109246  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:22.229172  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.120s	user 0.100s	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":150,"lbm_read_time_us":8226,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23395,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:20:22.229734  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=10.126437
I20260812 06:20:22.277864  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.048s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14930,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.278467  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:22.293563  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.294001  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:22.446262  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.152s	user 0.101s	sys 0.051s 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":234,"lbm_read_time_us":10961,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24825,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:20:22.446954  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=10.126437
I20260812 06:20:22.498734  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.051s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.499246  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:22.509848  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.510594  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:22.632236  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.121s	user 0.101s	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":233,"lbm_read_time_us":9612,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21516,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:22.632788  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=10.126437
I20260812 06:20:22.677634  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.045s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16185,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.678154  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:22.689095  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.689698  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:22.720667  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1541,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2126,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:22.721225  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling LogGCOp(7184c7f37b1a4ced99cf01975984fbb2): free 117302570 bytes of WAL
I20260812 06:20:22.721446  1135 log_reader.cc:385] T 7184c7f37b1a4ced99cf01975984fbb2: removed 12 log segments from log reader
I20260812 06:20:22.721509  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000003 (ops 11-15)
I20260812 06:20:22.721561  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000004 (ops 16-20)
I20260812 06:20:22.721619  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000005 (ops 21-25)
I20260812 06:20:22.721660  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000006 (ops 26-30)
I20260812 06:20:22.721695  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000007 (ops 31-34)
I20260812 06:20:22.721732  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000008 (ops 35-39)
I20260812 06:20:22.721768  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000009 (ops 40-44)
I20260812 06:20:22.721804  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000010 (ops 45-48)
I20260812 06:20:22.721841  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000011 (ops 49-53)
I20260812 06:20:22.721877  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000012 (ops 54-58)
I20260812 06:20:22.721912  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000013 (ops 59-63)
I20260812 06:20:22.721951  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000014 (ops 64-68)
I20260812 06:20:22.747812  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: LogGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:22.748322  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2): 473 bytes on disk
I20260812 06:20:22.749073  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.749658  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=3.181125
I20260812 06:20:22.769390  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7171,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:22.769841  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling LogGCOp(7184c7f37b1a4ced99cf01975984fbb2): free 11564875 bytes of WAL
I20260812 06:20:22.770033  1135 log_reader.cc:385] T 7184c7f37b1a4ced99cf01975984fbb2: removed 1 log segments from log reader
I20260812 06:20:22.770093  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000015 (ops 69-72)
I20260812 06:20:22.772228  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: LogGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:22.772495  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:22.782004  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3474,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.782593  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:22.940608  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.158s	user 0.120s	sys 0.038s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":628,"lbm_read_time_us":11125,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31101,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:20:22.941299  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:22.994630  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.053s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.995118  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:23.006131  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.006601  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:23.167909  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.161s	user 0.117s	sys 0.032s 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":438,"lbm_read_time_us":10775,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28155,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:20:23.168653  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:23.209133  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18450,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.209554  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:23.362351  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.153s	user 0.082s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":373,"lbm_read_time_us":9344,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25352,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:20:23.364558  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=11.118625
I20260812 06:20:23.401329  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.036s	user 0.012s	sys 0.020s Metrics: {"bytes_written":13086952,"delete_count":0,"lbm_write_time_us":15660,"lbm_writes_lt_1ms":322,"reinsert_count":0,"update_count":1595}
I20260812 06:20:23.401830  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:23.421985  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.020s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":5006,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:20:23.422506  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:23.433389  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4391,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.433997  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:23.619408  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.185s	user 0.123s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774790,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":683,"lbm_read_time_us":11234,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29986,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:23.620064  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:23.669441  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21867,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.670048  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:23.691763  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.021s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.692325  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:23.845202  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.153s	user 0.112s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":10126,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28635,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:20:23.845849  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:23.891065  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.045s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19618,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.891635  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:23.907568  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.908319  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:24.054148  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.146s	user 0.105s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":979,"lbm_read_time_us":8546,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29263,"lbm_writes_lt_1ms":543,"mutex_wait_us":257,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:20:24.054955  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=11.118625
I20260812 06:20:24.097924  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.043s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15623,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.098712  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=3.181125
I20260812 06:20:24.110387  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.011s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4348806,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:20:24.110853  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:24.120101  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":3289,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:20:24.120700  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:24.151286  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1341,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1819,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:24.151957  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling LogGCOp(7184c7f37b1a4ced99cf01975984fbb2): free 121006452 bytes of WAL
I20260812 06:20:24.152194  1135 log_reader.cc:385] T 7184c7f37b1a4ced99cf01975984fbb2: removed 12 log segments from log reader
I20260812 06:20:24.152235  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000016 (ops 73-77)
I20260812 06:20:24.152262  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000017 (ops 78-82)
I20260812 06:20:24.152326  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000018 (ops 83-86)
I20260812 06:20:24.152366  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000019 (ops 87-91)
I20260812 06:20:24.152406  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000020 (ops 92-96)
I20260812 06:20:24.152447  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000021 (ops 97-101)
I20260812 06:20:24.152489  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000022 (ops 102-106)
I20260812 06:20:24.152527  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000023 (ops 107-111)
I20260812 06:20:24.152566  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000024 (ops 112-116)
I20260812 06:20:24.152607  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000025 (ops 117-121)
I20260812 06:20:24.152647  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000026 (ops 122-126)
I20260812 06:20:24.152683  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000027 (ops 127-131)
I20260812 06:20:24.178493  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: LogGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:24.179010  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2): 481 bytes on disk
I20260812 06:20:24.179718  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.180334  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=4.173312
I20260812 06:20:24.193871  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5538513,"delete_count":0,"lbm_write_time_us":5658,"lbm_writes_lt_1ms":138,"reinsert_count":0,"update_count":675}
I20260812 06:20:24.194355  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.196750
I20260812 06:20:24.212729  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":3069,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:20:24.213378  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:24.437203  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.224s	user 0.155s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979827,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1091,"lbm_read_time_us":15213,"lbm_reads_lt_1ms":767,"lbm_write_time_us":36907,"lbm_writes_lt_1ms":743,"mutex_wait_us":306,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:20:24.437758  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=18.063937
I20260812 06:20:24.501933  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.064s	user 0.031s	sys 0.023s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26591,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:24.502504  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:24.513175  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.513635  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:24.714443  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.201s	user 0.140s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":12336,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33979,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:20:24.715133  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:24.763929  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.049s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21248,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.764597  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:24.776711  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4830,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.777197  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:24.945102  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.168s	user 0.104s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1425,"lbm_read_time_us":11119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29264,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45440,"update_count":2500}
I20260812 06:20:24.945822  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:25.008159  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.062s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22605,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.008759  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:25.019044  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.019497  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:25.199460  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.180s	user 0.127s	sys 0.046s 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":373,"lbm_read_time_us":13476,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29837,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:20:25.199993  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=14.095187
I20260812 06:20:25.255172  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.055s	user 0.031s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18588,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.255753  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:25.266813  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.267252  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:25.440145  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.173s	user 0.138s	sys 0.034s 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":400,"lbm_read_time_us":12966,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30760,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55680,"update_count":2500}
I20260812 06:20:25.440629  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=10.126437
I20260812 06:20:25.480593  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.040s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":17409,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.481344  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:25.499490  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.500046  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:25.635210  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.135s	user 0.127s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":7600,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26001,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:20:25.636144  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=10.126437
I20260812 06:20:25.673228  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.037s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16549,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.673719  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=2.188937
I20260812 06:20:25.686260  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.686833  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:25.718078  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushMRSOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1439,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1621,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:25.718822  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling LogGCOp(7184c7f37b1a4ced99cf01975984fbb2): free 132571605 bytes of WAL
I20260812 06:20:25.719053  1135 log_reader.cc:385] T 7184c7f37b1a4ced99cf01975984fbb2: removed 13 log segments from log reader
I20260812 06:20:25.719118  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000028 (ops 132-136)
I20260812 06:20:25.719172  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000029 (ops 137-140)
I20260812 06:20:25.719229  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000030 (ops 141-145)
I20260812 06:20:25.719270  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000031 (ops 146-150)
I20260812 06:20:25.719306  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000032 (ops 151-155)
I20260812 06:20:25.719357  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000033 (ops 156-160)
I20260812 06:20:25.719396  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000034 (ops 161-165)
I20260812 06:20:25.719434  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000035 (ops 166-170)
I20260812 06:20:25.719468  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000036 (ops 171-175)
I20260812 06:20:25.719517  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000037 (ops 176-180)
I20260812 06:20:25.719555  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000038 (ops 181-185)
I20260812 06:20:25.719592  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000039 (ops 186-190)
I20260812 06:20:25.719630  1135 log.cc:1079] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: Deleting log segment in path: /tmp/dist-test-taskFVGtgO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615424532-676-0/minicluster-data/ts-0-root/wals/7184c7f37b1a4ced99cf01975984fbb2/wal-000000040 (ops 191-194)
I20260812 06:20:25.745930  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: LogGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.027s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:20:25.746459  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=6.157687
I20260812 06:20:25.770633  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.024s	user 0.007s	sys 0.016s Metrics: {"bytes_written":7958933,"delete_count":0,"lbm_write_time_us":9905,"lbm_writes_lt_1ms":197,"reinsert_count":0,"update_count":970}
I20260812 06:20:25.771234  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2): 486 bytes on disk
I20260812 06:20:25.771636  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: UndoDeltaBlockGCOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.772138  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=1.000000
I20260812 06:20:25.841436   676 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.706s	user 1.770s	sys 0.167s
I20260812 06:20:25.928823   676 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.000s	sys 0.001s
I20260812 06:20:25.929365   676 tablet_server.cc:179] TabletServer@127.0.169.1:0 shutting down...
I20260812 06:20:25.931950  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: MajorDeltaCompactionOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.160s	user 0.143s	sys 0.016s Metrics: {"cfile_cache_miss":627,"cfile_cache_miss_bytes":28631075,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":365,"lbm_read_time_us":12738,"lbm_reads_lt_1ms":655,"lbm_write_time_us":31233,"lbm_writes_lt_1ms":637,"mutex_wait_us":53,"peak_mem_usage":74255878,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":80,"threads_started":1,"update_count":2970}
I20260812 06:20:25.932498  1240 maintenance_manager.cc:419] P 20a6684b08ff460492d6d4577999b662: Scheduling FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2): perf score=7.149875
I20260812 06:20:25.987043  1135 maintenance_manager.cc:643] P 20a6684b08ff460492d6d4577999b662: FlushDeltaMemStoresOp(7184c7f37b1a4ced99cf01975984fbb2) complete. Timing: real 0.054s	user 0.012s	sys 0.013s Metrics: {"bytes_written":8451227,"delete_count":0,"lbm_write_time_us":10574,"lbm_writes_lt_1ms":209,"reinsert_count":0,"update_count":1030}
I20260812 06:20:25.987601   676 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:25.987846   676 tablet_replica.cc:333] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662: stopping tablet replica
I20260812 06:20:25.987982   676 raft_consensus.cc:2243] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:25.988117   676 raft_consensus.cc:2272] T 7184c7f37b1a4ced99cf01975984fbb2 P 20a6684b08ff460492d6d4577999b662 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:25.991271   676 tablet_server.cc:196] TabletServer@127.0.169.1:0 shutdown complete.
I20260812 06:20:25.994060   676 master.cc:562] Master@127.0.169.62:40481 shutting down...
I20260812 06:20:25.997341   676 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:25.997516   676 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:25.997598   676 tablet_replica.cc:333] T 00000000000000000000000000000000 P e5554953d9bc484ab8276aea43a7b00f: stopping tablet replica
I20260812 06:20:26.009786   676 master.cc:584] Master@127.0.169.62:40481 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5193 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10660 ms total)

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