[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:02.563199  2771 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.180.254:37127
I20260812 06:17:02.564335  2771 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:02.564961  2771 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:02.572817  2777 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.573194  2776 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.572820  2771 server_base.cc:1061] running on GCE node
W20260812 06:17:02.572824  2779 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.573964  2771 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.574105  2771 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:02.574153  2771 hybrid_clock.cc:648] HybridClock initialized: now 1786515422574150 us; error 0 us; skew 500 ppm
I20260812 06:17:02.576318  2771 webserver.cc:533] Webserver started at http://127.2.180.254:43463/ using document root <none> and password file <none>
I20260812 06:17:02.576957  2771 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.577064  2771 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.577358  2771 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.579993  2771 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/master-0-root/instance:
uuid: "7ca02c8a3b424f6280aefeab20f0b541"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-8w9v"
I20260812 06:17:02.584559  2771 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:02.587190  2785 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.588517  2771 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:02.588680  2771 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/master-0-root
uuid: "7ca02c8a3b424f6280aefeab20f0b541"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-8w9v"
I20260812 06:17:02.588806  2771 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:02.614988  2771 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.615790  2771 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:02.616008  2771 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.624330  2771 rpc_server.cc:307] RPC server started. Bound to: 127.2.180.254:37127
I20260812 06:17:02.624383  2843 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.180.254:37127 every 8 connection(s)
I20260812 06:17:02.626721  2844 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.632763  2844 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541: Bootstrap starting.
I20260812 06:17:02.635268  2844 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.636335  2844 log.cc:826] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:02.638576  2844 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541: No bootstrap required, opened a new log
I20260812 06:17:02.641723  2844 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ca02c8a3b424f6280aefeab20f0b541" member_type: VOTER }
I20260812 06:17:02.641902  2844 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.641943  2844 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7ca02c8a3b424f6280aefeab20f0b541, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.642597  2844 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [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: "7ca02c8a3b424f6280aefeab20f0b541" member_type: VOTER }
I20260812 06:17:02.642743  2844 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.642791  2844 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.642889  2844 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.643702  2844 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ca02c8a3b424f6280aefeab20f0b541" member_type: VOTER }
I20260812 06:17:02.644181  2844 leader_election.cc:304] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [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: 7ca02c8a3b424f6280aefeab20f0b541; no voters: 
I20260812 06:17:02.644506  2844 leader_election.cc:290] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.644690  2847 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.644953  2847 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 1 LEADER]: Becoming Leader. State: Replica: 7ca02c8a3b424f6280aefeab20f0b541, State: Running, Role: LEADER
I20260812 06:17:02.645596  2844 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:02.645460  2847 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [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: "7ca02c8a3b424f6280aefeab20f0b541" member_type: VOTER }
I20260812 06:17:02.648383  2849 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7ca02c8a3b424f6280aefeab20f0b541. Latest consensus state: current_term: 1 leader_uuid: "7ca02c8a3b424f6280aefeab20f0b541" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ca02c8a3b424f6280aefeab20f0b541" member_type: VOTER } }
I20260812 06:17:02.648386  2848 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7ca02c8a3b424f6280aefeab20f0b541" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7ca02c8a3b424f6280aefeab20f0b541" member_type: VOTER } }
I20260812 06:17:02.648548  2848 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.648537  2849 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.648528  2771 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:02.649019  2862 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:02.651592  2862 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:02.656945  2862 catalog_manager.cc:1383] Generated new cluster ID: dfa875744e604f4397bc4ed70ade1135
I20260812 06:17:02.657047  2862 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:02.685565  2862 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:02.686558  2862 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:02.694128  2862 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541: Generated new TSK 0
I20260812 06:17:02.694854  2862 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:02.713711  2771 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:02.716820  2866 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.716903  2869 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:02.716997  2867 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:02.717417  2771 server_base.cc:1061] running on GCE node
I20260812 06:17:02.717634  2771 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.717680  2771 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:02.717696  2771 hybrid_clock.cc:648] HybridClock initialized: now 1786515422717697 us; error 0 us; skew 500 ppm
I20260812 06:17:02.718827  2771 webserver.cc:533] Webserver started at http://127.2.180.193:35503/ using document root <none> and password file <none>
I20260812 06:17:02.719023  2771 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.719087  2771 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.719198  2771 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.719628  2771 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/instance:
uuid: "973fe6988fb5441e8da735ce8c25b06c"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-8w9v"
I20260812 06:17:02.721252  2771 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:02.722287  2875 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.722543  2771 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:02.722617  2771 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root
uuid: "973fe6988fb5441e8da735ce8c25b06c"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-8w9v"
I20260812 06:17:02.722707  2771 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:02.736251  2771 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.736768  2771 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.737306  2771 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:02.738286  2771 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:02.738340  2771 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.738408  2771 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:02.738447  2771 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.745962  2771 rpc_server.cc:307] RPC server started. Bound to: 127.2.180.193:36697
I20260812 06:17:02.745995  2945 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.180.193:36697 every 8 connection(s)
I20260812 06:17:02.763666  2946 heartbeater.cc:344] Connected to a master server at 127.2.180.254:37127
I20260812 06:17:02.764008  2946 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:02.764605  2946 heartbeater.cc:507] Master 127.2.180.254:37127 requested a full tablet report, sending...
I20260812 06:17:02.766295  2804 ts_manager.cc:194] Registered new tserver with Master: 973fe6988fb5441e8da735ce8c25b06c (127.2.180.193:36697)
I20260812 06:17:02.766883  2771 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020183456s
I20260812 06:17:02.767865  2804 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49218
I20260812 06:17:02.776953  2804 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49226:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:02.793749  2905 tablet_service.cc:1511] Processing CreateTablet for tablet e9d90e1a302a489795c76776cde0713c (DEFAULT_TABLE table=heavy-update-compaction-test [id=b065919fc22e4bab9235f5725ebd1e20]), partition=
I20260812 06:17:02.794338  2905 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e9d90e1a302a489795c76776cde0713c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.798076  2958 tablet_bootstrap.cc:492] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Bootstrap starting.
I20260812 06:17:02.799906  2958 tablet_bootstrap.cc:654] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.802381  2958 tablet_bootstrap.cc:492] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: No bootstrap required, opened a new log
I20260812 06:17:02.802507  2958 ts_tablet_manager.cc:1403] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Time spent bootstrapping tablet: real 0.005s	user 0.000s	sys 0.004s
I20260812 06:17:02.803506  2958 raft_consensus.cc:359] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "973fe6988fb5441e8da735ce8c25b06c" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 36697 } }
I20260812 06:17:02.803620  2958 raft_consensus.cc:385] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.803645  2958 raft_consensus.cc:740] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 973fe6988fb5441e8da735ce8c25b06c, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.803802  2958 consensus_queue.cc:260] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [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: "973fe6988fb5441e8da735ce8c25b06c" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 36697 } }
I20260812 06:17:02.803895  2958 raft_consensus.cc:399] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.803925  2958 raft_consensus.cc:493] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.804001  2958 raft_consensus.cc:3060] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.805305  2958 raft_consensus.cc:515] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "973fe6988fb5441e8da735ce8c25b06c" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 36697 } }
I20260812 06:17:02.805428  2958 leader_election.cc:304] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [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: 973fe6988fb5441e8da735ce8c25b06c; no voters: 
I20260812 06:17:02.805721  2958 leader_election.cc:290] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.806025  2960 raft_consensus.cc:2804] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.806232  2958 ts_tablet_manager.cc:1434] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:02.806468  2960 raft_consensus.cc:697] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 1 LEADER]: Becoming Leader. State: Replica: 973fe6988fb5441e8da735ce8c25b06c, State: Running, Role: LEADER
I20260812 06:17:02.806605  2960 consensus_queue.cc:237] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [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: "973fe6988fb5441e8da735ce8c25b06c" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 36697 } }
I20260812 06:17:02.806766  2946 heartbeater.cc:499] Master 127.2.180.254:37127 was elected leader, sending a full tablet report...
I20260812 06:17:02.810204  2803 catalog_manager.cc:5719] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c reported cstate change: term changed from 0 to 1, leader changed from <none> to 973fe6988fb5441e8da735ce8c25b06c (127.2.180.193). New cstate: current_term: 1 leader_uuid: "973fe6988fb5441e8da735ce8c25b06c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "973fe6988fb5441e8da735ce8c25b06c" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 36697 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:02.893582  2771 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.076s	user 0.021s	sys 0.012s
I20260812 06:17:02.997313  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushMRSOp(e9d90e1a302a489795c76776cde0713c): perf score=10.125253
I20260812 06:17:03.137492  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushMRSOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.140s	user 0.126s	sys 0.012s Metrics: {"bytes_written":9312729,"cfile_init":1,"compiler_manager_pool.queue_time_us":405,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":820,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":30445,"lbm_writes_lt_1ms":484,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"spinlock_wait_cycles":170624,"thread_start_us":282,"threads_started":1,"update_count":1135}
I20260812 06:17:03.138896  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling LogGCOp(e9d90e1a302a489795c76776cde0713c): free 11976772 bytes of WAL
I20260812 06:17:03.139214  2880 log_reader.cc:385] T e9d90e1a302a489795c76776cde0713c: removed 1 log segments from log reader
I20260812 06:17:03.139281  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000001 (ops 1-6)
I20260812 06:17:03.142410  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: LogGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:03.142798  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=1.196750
I20260812 06:17:03.157838  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.015s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:17:03.158490  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:03.288540  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.130s	user 0.102s	sys 0.014s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487907,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1084,"lbm_read_time_us":5595,"lbm_reads_lt_1ms":364,"lbm_write_time_us":22522,"lbm_writes_lt_1ms":343,"mutex_wait_us":101,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":388,"threads_started":5,"update_count":1500}
I20260812 06:17:03.289240  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:03.340003  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.051s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":16157,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.340605  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c): 8206537 bytes on disk
I20260812 06:17:03.341135  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.341637  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:03.352078  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.352604  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:03.498401  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.146s	user 0.110s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590351,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":858,"lbm_read_time_us":10627,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25036,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2000}
I20260812 06:17:03.499114  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:03.537989  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.039s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16251,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.538578  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:03.552634  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.553122  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:03.708722  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.155s	user 0.109s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":720,"lbm_read_time_us":11494,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26242,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.709441  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:03.757019  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.047s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17036,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.757594  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:03.871791  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.114s	user 0.089s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487816,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1184,"lbm_read_time_us":7223,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21103,"lbm_writes_lt_1ms":343,"mutex_wait_us":454,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":1500}
I20260812 06:17:03.872368  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:03.923009  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.050s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16447,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.923605  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:03.934947  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.935539  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:04.064288  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.129s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":925,"lbm_read_time_us":9676,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27008,"lbm_writes_lt_1ms":443,"mutex_wait_us":250,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:17:04.064972  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:04.122888  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.058s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16972,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.123428  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:04.134552  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.135105  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:04.307942  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.173s	user 0.135s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":11534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26201,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.308764  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:04.362525  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.053s	user 0.035s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19599,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.363054  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:04.374308  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.374954  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:04.502319  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.127s	user 0.101s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":412,"lbm_read_time_us":7418,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27037,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:17:04.503003  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:04.549233  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.046s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16236,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:04.549768  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:04.561028  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.561666  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushMRSOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:04.596017  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushMRSOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1516,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1426,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:04.597056  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling LogGCOp(e9d90e1a302a489795c76776cde0713c): free 121006429 bytes of WAL
I20260812 06:17:04.597373  2880 log_reader.cc:385] T e9d90e1a302a489795c76776cde0713c: removed 12 log segments from log reader
I20260812 06:17:04.597445  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000002 (ops 7-11)
I20260812 06:17:04.597492  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000003 (ops 12-16)
I20260812 06:17:04.597523  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000004 (ops 17-21)
I20260812 06:17:04.597563  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000005 (ops 22-26)
I20260812 06:17:04.597592  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000006 (ops 27-31)
I20260812 06:17:04.597628  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000007 (ops 32-36)
I20260812 06:17:04.597676  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000008 (ops 37-41)
I20260812 06:17:04.597707  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000009 (ops 42-46)
I20260812 06:17:04.597744  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000010 (ops 47-51)
I20260812 06:17:04.597786  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000011 (ops 52-56)
I20260812 06:17:04.597826  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000012 (ops 57-60)
I20260812 06:17:04.597865  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000013 (ops 61-65)
I20260812 06:17:04.625088  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: LogGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:04.625532  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=3.181125
I20260812 06:17:04.639087  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4559,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:04.639573  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:04.650194  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.650750  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c): 473 bytes on disk
I20260812 06:17:04.651206  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.651904  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:04.834066  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.182s	user 0.126s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795397,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":305,"lbm_read_time_us":11399,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36463,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:17:04.834578  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=14.095187
I20260812 06:17:04.889460  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.055s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24209,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.889953  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:04.902257  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.902877  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:05.055877  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.153s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":11024,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30593,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:05.056645  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=11.118625
I20260812 06:17:05.103480  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.047s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22951,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:17:05.104092  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:05.129984  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.026s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4948,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.130535  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:05.140908  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3853,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.141566  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:05.327112  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.185s	user 0.143s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":354,"lbm_read_time_us":11301,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30801,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:17:05.327808  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=14.095187
I20260812 06:17:05.371263  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.043s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18967,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.371873  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:05.508613  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.136s	user 0.105s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590228,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":179,"lbm_read_time_us":8971,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24170,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:05.509415  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:05.542980  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.033s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15319,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.543541  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:05.561474  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.018s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.561988  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:05.696445  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.134s	user 0.109s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":286,"lbm_read_time_us":7361,"lbm_reads_lt_1ms":468,"lbm_write_time_us":30316,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:17:05.697286  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:05.762404  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.065s	user 0.042s	sys 0.002s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.763067  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:05.780661  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.781487  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:05.925832  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.144s	user 0.097s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":10781,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31207,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:17:05.926680  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=6.157687
I20260812 06:17:05.956573  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11507,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:05.957230  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:06.076661  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.118s	user 0.087s	sys 0.025s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12385404,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1991,"lbm_read_time_us":11706,"lbm_reads_1-10_ms":2,"lbm_reads_lt_1ms":261,"lbm_write_time_us":14558,"lbm_writes_lt_1ms":243,"mutex_wait_us":695,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1000}
I20260812 06:17:06.077334  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=6.157687
I20260812 06:17:06.109063  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13122,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:06.109704  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushMRSOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:06.151347  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushMRSOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.041s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1631,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1496,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:06.152267  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling LogGCOp(e9d90e1a302a489795c76776cde0713c): free 112239316 bytes of WAL
I20260812 06:17:06.152611  2880 log_reader.cc:385] T e9d90e1a302a489795c76776cde0713c: removed 11 log segments from log reader
I20260812 06:17:06.152690  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000014 (ops 66-70)
I20260812 06:17:06.152745  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000015 (ops 71-75)
I20260812 06:17:06.152834  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000016 (ops 76-80)
I20260812 06:17:06.152884  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000017 (ops 81-85)
I20260812 06:17:06.152962  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000018 (ops 86-90)
I20260812 06:17:06.153010  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000019 (ops 91-94)
I20260812 06:17:06.153048  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000020 (ops 95-99)
I20260812 06:17:06.153092  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000021 (ops 100-104)
I20260812 06:17:06.153136  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000022 (ops 105-109)
I20260812 06:17:06.153179  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000023 (ops 110-114)
I20260812 06:17:06.153223  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000024 (ops 115-119)
I20260812 06:17:06.186396  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: LogGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.034s	user 0.002s	sys 0.028s Metrics: {}
I20260812 06:17:06.187008  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=3.181125
I20260812 06:17:06.210954  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.024s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4682,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:06.211469  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling LogGCOp(e9d90e1a302a489795c76776cde0713c): free 12017932 bytes of WAL
I20260812 06:17:06.211715  2880 log_reader.cc:385] T e9d90e1a302a489795c76776cde0713c: removed 1 log segments from log reader
I20260812 06:17:06.211761  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000025 (ops 120-124)
I20260812 06:17:06.214164  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: LogGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:06.214511  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:06.226468  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4001,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:06.227181  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c): 446 bytes on disk
I20260812 06:17:06.227946  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":115,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.228839  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:06.361472  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.132s	user 0.081s	sys 0.051s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20590456,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":177,"lbm_read_time_us":8113,"lbm_reads_lt_1ms":465,"lbm_write_time_us":23702,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":86,"threads_started":1,"update_count":2000}
I20260812 06:17:06.363903  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:06.405346  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.041s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15924,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.405829  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:06.418363  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.419098  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:06.538694  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.119s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":946,"lbm_read_time_us":9222,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22546,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:17:06.539322  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:06.588654  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.049s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15078,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.589430  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:06.607533  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.608357  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:06.760331  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.152s	user 0.123s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":785,"lbm_read_time_us":10772,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25300,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:17:06.760993  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:06.809670  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.048s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17573,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.810204  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:06.822584  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.823305  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:06.957706  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.134s	user 0.095s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1073,"lbm_read_time_us":10659,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27078,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.958186  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=10.126437
I20260812 06:17:07.010039  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.052s	user 0.020s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23086,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.010684  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.023644  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.024317  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:07.165050  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.141s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":915,"lbm_read_time_us":11038,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31964,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":440,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:17:07.165705  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=11.118625
I20260812 06:17:07.215571  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.050s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18544,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.216180  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.234566  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.235074  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.244911  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3753,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.245388  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:07.418015  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.172s	user 0.120s	sys 0.050s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692868,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":608,"lbm_read_time_us":11740,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32701,"lbm_writes_lt_1ms":543,"mutex_wait_us":7,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:07.418804  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=11.118625
I20260812 06:17:07.471657  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.053s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18620,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.472342  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=3.181125
I20260812 06:17:07.484862  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4471880,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:17:07.485397  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.494925  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":3403,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:07.495406  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushMRSOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:07.528652  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushMRSOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1909,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1389,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:07.529403  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling LogGCOp(e9d90e1a302a489795c76776cde0713c): free 108535664 bytes of WAL
I20260812 06:17:07.529637  2880 log_reader.cc:385] T e9d90e1a302a489795c76776cde0713c: removed 11 log segments from log reader
I20260812 06:17:07.529683  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000026 (ops 125-129)
I20260812 06:17:07.529712  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000027 (ops 130-134)
I20260812 06:17:07.529771  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000028 (ops 135-139)
I20260812 06:17:07.529815  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000029 (ops 140-144)
I20260812 06:17:07.529858  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000030 (ops 145-148)
I20260812 06:17:07.529899  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000031 (ops 149-153)
I20260812 06:17:07.529960  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000032 (ops 154-158)
I20260812 06:17:07.529996  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000033 (ops 159-162)
I20260812 06:17:07.530037  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000034 (ops 163-167)
I20260812 06:17:07.530081  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000035 (ops 168-172)
I20260812 06:17:07.530154  2880 log.cc:1079] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/e9d90e1a302a489795c76776cde0713c/wal-000000036 (ops 173-177)
I20260812 06:17:07.555001  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: LogGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:07.555428  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.581008  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.025s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.581635  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.592908  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.593583  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c): 448 bytes on disk
I20260812 06:17:07.594326  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: UndoDeltaBlockGCOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":132,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.595402  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:07.840186  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.245s	user 0.160s	sys 0.078s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32897926,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":12054,"dirs.run_cpu_time_us":641,"dirs.run_wall_time_us":3807,"lbm_read_time_us":17193,"lbm_reads_lt_1ms":775,"lbm_write_time_us":43675,"lbm_writes_lt_1ms":743,"mutex_wait_us":6513,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3500}
I20260812 06:17:07.840950  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=15.087375
I20260812 06:17:07.893569  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.052s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23129,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:07.894145  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.911134  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4368,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.911669  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=2.188937
I20260812 06:17:07.922863  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.923574  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c): perf score=1.000000
I20260812 06:17:08.112361  2771 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.219s	user 1.915s	sys 0.124s
I20260812 06:17:08.114699  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: MajorDeltaCompactionOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.191s	user 0.145s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":140,"lbm_read_time_us":13929,"lbm_reads_lt_1ms":673,"lbm_write_time_us":41883,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:17:08.115410  2947 maintenance_manager.cc:419] P 973fe6988fb5441e8da735ce8c25b06c: Scheduling FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c): perf score=14.095187
I20260812 06:17:08.141360  2771 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.028s	user 0.003s	sys 0.000s
I20260812 06:17:08.142035  2771 tablet_server.cc:179] TabletServer@127.2.180.193:0 shutting down...
I20260812 06:17:08.172566  2880 maintenance_manager.cc:643] P 973fe6988fb5441e8da735ce8c25b06c: FlushDeltaMemStoresOp(e9d90e1a302a489795c76776cde0713c) complete. Timing: real 0.057s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29116,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.173235  2771 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:08.173682  2771 tablet_replica.cc:333] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c: stopping tablet replica
I20260812 06:17:08.173934  2771 raft_consensus.cc:2243] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:08.174141  2771 raft_consensus.cc:2272] T e9d90e1a302a489795c76776cde0713c P 973fe6988fb5441e8da735ce8c25b06c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:08.180043  2771 tablet_server.cc:196] TabletServer@127.2.180.193:0 shutdown complete.
I20260812 06:17:08.184883  2771 master.cc:562] Master@127.2.180.254:37127 shutting down...
I20260812 06:17:08.189764  2771 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:08.189983  2771 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:08.190083  2771 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7ca02c8a3b424f6280aefeab20f0b541: stopping tablet replica
I20260812 06:17:08.202886  2771 master.cc:584] Master@127.2.180.254:37127 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5735 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:08.298185  2771 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.180.254:38143
I20260812 06:17:08.298614  2771 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:08.301163  2980 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:08.301139  2982 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.301332  2771 server_base.cc:1061] running on GCE node
W20260812 06:17:08.301102  2979 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.301633  2771 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:08.301682  2771 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:08.301697  2771 hybrid_clock.cc:648] HybridClock initialized: now 1786515428301698 us; error 0 us; skew 500 ppm
I20260812 06:17:08.302582  2771 webserver.cc:533] Webserver started at http://127.2.180.254:45857/ using document root <none> and password file <none>
I20260812 06:17:08.302731  2771 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:08.302776  2771 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:08.302836  2771 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:08.303217  2771 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/master-0-root/instance:
uuid: "f26e5c144b664ea082f05949aaba2a97"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-8w9v"
I20260812 06:17:08.305141  2771 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:08.306315  2988 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.306680  2771 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:08.306784  2771 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/master-0-root
uuid: "f26e5c144b664ea082f05949aaba2a97"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-8w9v"
I20260812 06:17:08.306881  2771 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:08.313601  2771 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:08.314043  2771 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:08.318783  2771 rpc_server.cc:307] RPC server started. Bound to: 127.2.180.254:38143
I20260812 06:17:08.319000  3043 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.180.254:38143 every 8 connection(s)
I20260812 06:17:08.321586  3044 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:08.339174  3044 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97: Bootstrap starting.
I20260812 06:17:08.340186  3044 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:08.341559  3044 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97: No bootstrap required, opened a new log
I20260812 06:17:08.342115  3044 raft_consensus.cc:359] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26e5c144b664ea082f05949aaba2a97" member_type: VOTER }
I20260812 06:17:08.342223  3044 raft_consensus.cc:385] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:08.342252  3044 raft_consensus.cc:740] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f26e5c144b664ea082f05949aaba2a97, State: Initialized, Role: FOLLOWER
I20260812 06:17:08.342453  3044 consensus_queue.cc:260] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [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: "f26e5c144b664ea082f05949aaba2a97" member_type: VOTER }
I20260812 06:17:08.342536  3044 raft_consensus.cc:399] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:08.342564  3044 raft_consensus.cc:493] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:08.342599  3044 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:08.343467  3044 raft_consensus.cc:515] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26e5c144b664ea082f05949aaba2a97" member_type: VOTER }
I20260812 06:17:08.343621  3044 leader_election.cc:304] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [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: f26e5c144b664ea082f05949aaba2a97; no voters: 
I20260812 06:17:08.343901  3044 leader_election.cc:290] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:08.344193  3047 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:08.344457  3047 raft_consensus.cc:697] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 1 LEADER]: Becoming Leader. State: Replica: f26e5c144b664ea082f05949aaba2a97, State: Running, Role: LEADER
I20260812 06:17:08.344477  3044 sys_catalog.cc:565] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:08.344653  3047 consensus_queue.cc:237] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [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: "f26e5c144b664ea082f05949aaba2a97" member_type: VOTER }
I20260812 06:17:08.345124  3050 sys_catalog.cc:455] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f26e5c144b664ea082f05949aaba2a97. Latest consensus state: current_term: 1 leader_uuid: "f26e5c144b664ea082f05949aaba2a97" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26e5c144b664ea082f05949aaba2a97" member_type: VOTER } }
I20260812 06:17:08.345291  3050 sys_catalog.cc:458] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:08.345393  3048 sys_catalog.cc:455] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f26e5c144b664ea082f05949aaba2a97" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26e5c144b664ea082f05949aaba2a97" member_type: VOTER } }
I20260812 06:17:08.345512  3048 sys_catalog.cc:458] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:08.345949  3055 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:08.346627  3055 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:08.346817  2771 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:08.348645  3055 catalog_manager.cc:1383] Generated new cluster ID: 4e98bd67dab24514b37090d807177637
I20260812 06:17:08.348716  3055 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:08.368947  3055 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:08.369591  3055 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:08.382804  3055 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97: Generated new TSK 0
I20260812 06:17:08.383013  3055 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:08.411796  2771 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:08.413877  3069 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:08.414023  3072 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:08.414076  3068 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.414263  2771 server_base.cc:1061] running on GCE node
I20260812 06:17:08.414429  2771 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:08.414482  2771 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:08.414500  2771 hybrid_clock.cc:648] HybridClock initialized: now 1786515428414500 us; error 0 us; skew 500 ppm
I20260812 06:17:08.415442  2771 webserver.cc:533] Webserver started at http://127.2.180.193:34023/ using document root <none> and password file <none>
I20260812 06:17:08.415632  2771 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:08.415689  2771 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:08.415793  2771 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:08.416360  2771 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/instance:
uuid: "ad8e46ab7cb64b9797410122f5563b29"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-8w9v"
I20260812 06:17:08.417948  2771 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:08.419001  3080 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.419271  2771 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:08.419344  2771 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root
uuid: "ad8e46ab7cb64b9797410122f5563b29"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-8w9v"
I20260812 06:17:08.419452  2771 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:08.438493  2771 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:08.438946  2771 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:08.439296  2771 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:08.439798  2771 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:08.439837  2771 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.439901  2771 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:08.439942  2771 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.444525  2771 rpc_server.cc:307] RPC server started. Bound to: 127.2.180.193:34813
I20260812 06:17:08.444602  3151 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.180.193:34813 every 8 connection(s)
I20260812 06:17:08.454119  3152 heartbeater.cc:344] Connected to a master server at 127.2.180.254:38143
I20260812 06:17:08.454265  3152 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:08.454568  3152 heartbeater.cc:507] Master 127.2.180.254:38143 requested a full tablet report, sending...
I20260812 06:17:08.455340  3006 ts_manager.cc:194] Registered new tserver with Master: ad8e46ab7cb64b9797410122f5563b29 (127.2.180.193:34813)
I20260812 06:17:08.456112  3006 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42758
I20260812 06:17:08.456300  2771 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011272802s
I20260812 06:17:08.463908  3006 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42762:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:08.473358  3113 tablet_service.cc:1511] Processing CreateTablet for tablet c55105de876b468885b0662b97cd3947 (DEFAULT_TABLE table=heavy-update-compaction-test [id=214bf31a837e4406a7023e1b4c882093]), partition=
I20260812 06:17:08.473651  3113 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c55105de876b468885b0662b97cd3947. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:08.475840  3164 tablet_bootstrap.cc:492] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Bootstrap starting.
I20260812 06:17:08.476852  3164 tablet_bootstrap.cc:654] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:08.478039  3164 tablet_bootstrap.cc:492] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: No bootstrap required, opened a new log
I20260812 06:17:08.478137  3164 ts_tablet_manager.cc:1403] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:08.478672  3164 raft_consensus.cc:359] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad8e46ab7cb64b9797410122f5563b29" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 34813 } }
I20260812 06:17:08.478791  3164 raft_consensus.cc:385] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:08.478825  3164 raft_consensus.cc:740] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ad8e46ab7cb64b9797410122f5563b29, State: Initialized, Role: FOLLOWER
I20260812 06:17:08.478976  3164 consensus_queue.cc:260] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [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: "ad8e46ab7cb64b9797410122f5563b29" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 34813 } }
I20260812 06:17:08.479074  3164 raft_consensus.cc:399] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:08.479099  3164 raft_consensus.cc:493] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:08.479135  3164 raft_consensus.cc:3060] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:08.479833  3164 raft_consensus.cc:515] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad8e46ab7cb64b9797410122f5563b29" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 34813 } }
I20260812 06:17:08.479954  3164 leader_election.cc:304] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [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: ad8e46ab7cb64b9797410122f5563b29; no voters: 
I20260812 06:17:08.480182  3164 leader_election.cc:290] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:08.480274  3166 raft_consensus.cc:2804] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:08.480448  3166 raft_consensus.cc:697] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 1 LEADER]: Becoming Leader. State: Replica: ad8e46ab7cb64b9797410122f5563b29, State: Running, Role: LEADER
I20260812 06:17:08.480541  3164 ts_tablet_manager.cc:1434] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:08.480576  3152 heartbeater.cc:499] Master 127.2.180.254:38143 was elected leader, sending a full tablet report...
I20260812 06:17:08.480670  3166 consensus_queue.cc:237] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [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: "ad8e46ab7cb64b9797410122f5563b29" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 34813 } }
I20260812 06:17:08.482100  3006 catalog_manager.cc:5719] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 reported cstate change: term changed from 0 to 1, leader changed from <none> to ad8e46ab7cb64b9797410122f5563b29 (127.2.180.193). New cstate: current_term: 1 leader_uuid: "ad8e46ab7cb64b9797410122f5563b29" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad8e46ab7cb64b9797410122f5563b29" member_type: VOTER last_known_addr { host: "127.2.180.193" port: 34813 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:08.541659  2771 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.019s	sys 0.004s
I20260812 06:17:08.695551  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushMRSOp(c55105de876b468885b0662b97cd3947): perf score=19.054940
I20260812 06:17:08.847540  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushMRSOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.152s	user 0.104s	sys 0.044s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":936,"drs_written":1,"lbm_read_time_us":134,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37852,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:08.848345  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling LogGCOp(c55105de876b468885b0662b97cd3947): free 20290830 bytes of WAL
I20260812 06:17:08.848590  3086 log_reader.cc:385] T c55105de876b468885b0662b97cd3947: removed 2 log segments from log reader
I20260812 06:17:08.848649  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000001 (ops 1-6)
I20260812 06:17:08.848697  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000002 (ops 7-10)
I20260812 06:17:08.854220  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: LogGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:08.854671  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:08.873458  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.019s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.873991  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:09.019959  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.146s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":57,"lbm_read_time_us":10658,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25832,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":579,"threads_started":5,"update_count":2000}
I20260812 06:17:09.020884  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:09.067803  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.047s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18602,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.068352  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:09.078891  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.010s	user 0.004s	sys 0.004s 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:17:09.079655  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:09.210237  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.130s	user 0.110s	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":282,"lbm_read_time_us":9292,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25393,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30720,"update_count":2000}
I20260812 06:17:09.210786  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947): 16411396 bytes on disk
I20260812 06:17:09.211269  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.211752  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:09.266610  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.055s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15238,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.267198  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:09.280005  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.280581  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:09.436679  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.156s	user 0.097s	sys 0.058s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":978,"lbm_read_time_us":10998,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24690,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.437289  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:09.485329  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.048s	user 0.015s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17888,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.485932  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:09.497188  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.498037  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:09.636090  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.138s	user 0.102s	sys 0.033s 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":278,"lbm_read_time_us":10161,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24772,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:17:09.636665  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:09.686350  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.050s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16494,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.686852  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:09.697611  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.698374  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:09.841298  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.143s	user 0.119s	sys 0.019s 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":526,"lbm_read_time_us":10426,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26712,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:09.842008  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:09.899778  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.058s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17079,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.900475  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:09.911783  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.912338  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:10.059387  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.147s	user 0.114s	sys 0.033s 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":1046,"lbm_read_time_us":10901,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22781,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:10.060241  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:10.098311  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.038s	user 0.021s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.098918  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:10.115200  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.115907  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushMRSOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:10.146036  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushMRSOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.030s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1632,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1637,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:10.146764  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling LogGCOp(c55105de876b468885b0662b97cd3947): free 108535442 bytes of WAL
I20260812 06:17:10.147042  3086 log_reader.cc:385] T c55105de876b468885b0662b97cd3947: removed 11 log segments from log reader
I20260812 06:17:10.147104  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000003 (ops 11-15)
I20260812 06:17:10.147145  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000004 (ops 16-20)
I20260812 06:17:10.147181  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000005 (ops 21-24)
I20260812 06:17:10.147205  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000006 (ops 25-29)
I20260812 06:17:10.147235  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000007 (ops 30-34)
I20260812 06:17:10.147264  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000008 (ops 35-39)
I20260812 06:17:10.147291  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000009 (ops 40-44)
I20260812 06:17:10.147323  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000010 (ops 45-49)
I20260812 06:17:10.147348  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000011 (ops 50-54)
I20260812 06:17:10.147382  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000012 (ops 55-58)
I20260812 06:17:10.147413  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000013 (ops 59-63)
I20260812 06:17:10.172170  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: LogGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.025s	user 0.001s	sys 0.024s Metrics: {}
I20260812 06:17:10.172690  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:10.206290  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.033s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.206835  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:10.217978  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.218457  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947): 447 bytes on disk
I20260812 06:17:10.218887  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.219345  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:10.424084  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.205s	user 0.128s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1010,"lbm_read_time_us":14371,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33687,"lbm_writes_lt_1ms":643,"mutex_wait_us":510,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:17:10.424991  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:10.491694  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.066s	user 0.029s	sys 0.034s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.492339  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:10.503886  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.504406  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:10.699002  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.194s	user 0.123s	sys 0.070s 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":809,"lbm_read_time_us":15583,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30881,"lbm_writes_lt_1ms":543,"mutex_wait_us":266,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:17:10.702896  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:10.753789  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22398,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.754359  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:10.778426  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.024s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.779052  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:10.955133  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.176s	user 0.131s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":12564,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29129,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:17:10.955659  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:11.011302  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.055s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.012161  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:11.028594  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.016s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.029109  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:11.206862  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.178s	user 0.115s	sys 0.057s 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":203,"lbm_read_time_us":10607,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27394,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:17:11.207470  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:11.265236  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.058s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27051,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.265825  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:11.279726  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.280309  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:11.445441  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.165s	user 0.120s	sys 0.042s 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":640,"lbm_read_time_us":11605,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29671,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:17:11.445977  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:11.506613  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.060s	user 0.021s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24236,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.507300  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:11.524147  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.524698  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:11.690791  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.166s	user 0.137s	sys 0.028s 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":2002,"lbm_read_time_us":13168,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35743,"lbm_writes_lt_1ms":543,"mutex_wait_us":717,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:17:11.691622  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:11.742331  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.050s	user 0.029s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":22848,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:11.742944  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:11.759783  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.760361  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushMRSOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:11.795111  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushMRSOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1536,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1975,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:11.795830  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling LogGCOp(c55105de876b468885b0662b97cd3947): free 132571312 bytes of WAL
I20260812 06:17:11.796085  3086 log_reader.cc:385] T c55105de876b468885b0662b97cd3947: removed 13 log segments from log reader
I20260812 06:17:11.796171  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000014 (ops 64-68)
I20260812 06:17:11.796229  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000015 (ops 69-73)
I20260812 06:17:11.796271  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000016 (ops 74-78)
I20260812 06:17:11.796290  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000017 (ops 79-83)
I20260812 06:17:11.796342  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000018 (ops 84-88)
I20260812 06:17:11.796380  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000019 (ops 89-92)
I20260812 06:17:11.796419  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000020 (ops 93-97)
I20260812 06:17:11.796456  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000021 (ops 98-102)
I20260812 06:17:11.796494  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000022 (ops 103-107)
I20260812 06:17:11.796533  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000023 (ops 108-112)
I20260812 06:17:11.796571  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000024 (ops 113-117)
I20260812 06:17:11.796613  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000025 (ops 118-122)
I20260812 06:17:11.796638  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000026 (ops 123-126)
I20260812 06:17:11.826179  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: LogGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:11.826758  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=5.165500
I20260812 06:17:11.849150  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.022s	user 0.012s	sys 0.009s Metrics: {"bytes_written":6974354,"delete_count":0,"lbm_write_time_us":9019,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:17:11.849869  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling LogGCOp(c55105de876b468885b0662b97cd3947): free 8767078 bytes of WAL
I20260812 06:17:11.850167  3086 log_reader.cc:385] T c55105de876b468885b0662b97cd3947: removed 1 log segments from log reader
I20260812 06:17:11.850216  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000027 (ops 127-131)
I20260812 06:17:11.852098  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: LogGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:11.852733  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947): 493 bytes on disk
I20260812 06:17:11.853495  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":123,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.854199  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:11.860277  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.006s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1230902,"delete_count":0,"lbm_write_time_us":1682,"lbm_writes_lt_1ms":33,"reinsert_count":0,"update_count":150}
I20260812 06:17:11.860726  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:12.012775  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.152s	user 0.111s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2915,"lbm_read_time_us":11099,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30459,"lbm_writes_lt_1ms":643,"mutex_wait_us":830,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:17:12.013532  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:12.056315  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.043s	user 0.037s	sys 0.005s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18320,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.056839  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:12.070504  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.071035  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:12.230857  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.160s	user 0.107s	sys 0.050s 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":188,"lbm_read_time_us":9342,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32212,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":118016,"update_count":2500}
I20260812 06:17:12.231511  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:12.263854  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.032s	user 0.013s	sys 0.015s Metrics: {"bytes_written":12348515,"delete_count":0,"lbm_write_time_us":14326,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1505}
I20260812 06:17:12.264487  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:12.280025  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6215,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:12.280658  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:12.430449  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.150s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":10650,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23802,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:17:12.431306  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=11.118625
I20260812 06:17:12.473277  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.042s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18209,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.473788  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:12.507804  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.034s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4103,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.508730  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:12.519852  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.520453  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:12.702499  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.182s	user 0.088s	sys 0.084s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":318,"lbm_read_time_us":14094,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29509,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:12.703140  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:12.754736  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.051s	user 0.028s	sys 0.021s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22471,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.755230  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:12.768005  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.013s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.768791  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:12.968466  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.199s	user 0.123s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":15018,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31334,"lbm_writes_lt_1ms":543,"mutex_wait_us":400,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:12.969028  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:13.019539  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.050s	user 0.030s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18983,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.020098  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:13.032317  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.032828  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:13.204493  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.171s	user 0.131s	sys 0.033s 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":778,"lbm_read_time_us":12435,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32060,"lbm_writes_lt_1ms":543,"mutex_wait_us":373,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:13.205227  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=10.126437
I20260812 06:17:13.254230  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.049s	user 0.025s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22896,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.255070  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:13.274859  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.020s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.275938  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushMRSOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:13.315941  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushMRSOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.040s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1429,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1870,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:13.317008  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947): 472 bytes on disk
I20260812 06:17:13.317515  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: UndoDeltaBlockGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.318140  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=3.181125
I20260812 06:17:13.339020  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.021s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7719,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:13.339504  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling LogGCOp(c55105de876b468885b0662b97cd3947): free 124257569 bytes of WAL
I20260812 06:17:13.339731  3086 log_reader.cc:385] T c55105de876b468885b0662b97cd3947: removed 12 log segments from log reader
I20260812 06:17:13.339780  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000028 (ops 132-136)
I20260812 06:17:13.339810  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000029 (ops 137-141)
I20260812 06:17:13.339879  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000030 (ops 142-146)
I20260812 06:17:13.339915  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000031 (ops 147-150)
I20260812 06:17:13.339948  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000032 (ops 151-155)
I20260812 06:17:13.339975  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000033 (ops 156-160)
I20260812 06:17:13.340013  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000034 (ops 161-165)
I20260812 06:17:13.340051  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000035 (ops 166-170)
I20260812 06:17:13.340093  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000036 (ops 171-175)
I20260812 06:17:13.340164  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000037 (ops 176-180)
I20260812 06:17:13.340207  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000038 (ops 181-185)
I20260812 06:17:13.340245  3086 log.cc:1079] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: Deleting log segment in path: /tmp/dist-test-taskdCrrds/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422551592-2771-0/minicluster-data/ts-0-root/wals/c55105de876b468885b0662b97cd3947/wal-000000039 (ops 186-190)
I20260812 06:17:13.368458  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: LogGCOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:13.368897  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:13.398046  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.029s	user 0.008s	sys 0.016s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4579,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.398716  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=2.188937
I20260812 06:17:13.414839  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.415395  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:13.636271  2771 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.094s	user 1.861s	sys 0.206s
I20260812 06:17:13.651398  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.236s	user 0.146s	sys 0.087s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":17748,"lbm_reads_lt_1ms":771,"lbm_write_time_us":43804,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3500}
I20260812 06:17:13.651922  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947): perf score=14.095187
I20260812 06:17:13.684943  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: FlushDeltaMemStoresOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.033s	user 0.012s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16212,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:13.685465  3153 maintenance_manager.cc:419] P ad8e46ab7cb64b9797410122f5563b29: Scheduling MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947): perf score=1.000000
I20260812 06:17:13.729249  2771 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.003s	sys 0.000s
I20260812 06:17:13.729753  2771 tablet_server.cc:179] TabletServer@127.2.180.193:0 shutting down...
I20260812 06:17:13.851893  3086 maintenance_manager.cc:643] P ad8e46ab7cb64b9797410122f5563b29: MajorDeltaCompactionOp(c55105de876b468885b0662b97cd3947) complete. Timing: real 0.166s	user 0.077s	sys 0.051s 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":569,"lbm_read_time_us":8580,"lbm_reads_lt_1ms":467,"lbm_write_time_us":57216,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":126,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:17:13.852663  2771 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:13.852947  2771 tablet_replica.cc:333] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29: stopping tablet replica
I20260812 06:17:13.853106  2771 raft_consensus.cc:2243] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:13.853307  2771 raft_consensus.cc:2272] T c55105de876b468885b0662b97cd3947 P ad8e46ab7cb64b9797410122f5563b29 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:13.868592  2771 tablet_server.cc:196] TabletServer@127.2.180.193:0 shutdown complete.
I20260812 06:17:13.892488  2771 master.cc:562] Master@127.2.180.254:38143 shutting down...
I20260812 06:17:13.896520  2771 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:13.896740  2771 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:13.896858  2771 tablet_replica.cc:333] T 00000000000000000000000000000000 P f26e5c144b664ea082f05949aaba2a97: stopping tablet replica
I20260812 06:17:13.909389  2771 master.cc:584] Master@127.2.180.254:38143 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5697 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11434 ms total)

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