[==========] 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:18:36.376793 15805 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.111.126:37839
I20260812 06:18:36.378013 15805 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:18:36.378813 15805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:36.386684 15810 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.386842 15811 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.386894 15805 server_base.cc:1061] running on GCE node
W20260812 06:18:36.387068 15813 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.387627 15805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:36.387758 15805 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:36.387828 15805 hybrid_clock.cc:648] HybridClock initialized: now 1786515516387826 us; error 0 us; skew 500 ppm
I20260812 06:18:36.389990 15805 webserver.cc:533] Webserver started at http://127.15.111.126:42161/ using document root <none> and password file <none>
I20260812 06:18:36.390676 15805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:36.390772 15805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:36.391054 15805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:36.393249 15805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/master-0-root/instance:
uuid: "10f7a8de53714ceea0e1c6731e809fe6"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-dhph"
I20260812 06:18:36.397917 15805 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.004s
I20260812 06:18:36.400604 15820 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.401932 15805 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:36.402108 15805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/master-0-root
uuid: "10f7a8de53714ceea0e1c6731e809fe6"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-dhph"
I20260812 06:18:36.402300 15805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.444783 15805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.445537 15805 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:18:36.445734 15805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.454409 15805 rpc_server.cc:307] RPC server started. Bound to: 127.15.111.126:37839
I20260812 06:18:36.454459 15877 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.111.126:37839 every 8 connection(s)
I20260812 06:18:36.457060 15878 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.463760 15878 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6: Bootstrap starting.
I20260812 06:18:36.466807 15878 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.467931 15878 log.cc:826] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:36.470147 15878 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6: No bootstrap required, opened a new log
I20260812 06:18:36.473553 15878 raft_consensus.cc:359] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10f7a8de53714ceea0e1c6731e809fe6" member_type: VOTER }
I20260812 06:18:36.473788 15878 raft_consensus.cc:385] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.473848 15878 raft_consensus.cc:740] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 10f7a8de53714ceea0e1c6731e809fe6, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.474555 15878 consensus_queue.cc:260] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [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: "10f7a8de53714ceea0e1c6731e809fe6" member_type: VOTER }
I20260812 06:18:36.474843 15878 raft_consensus.cc:399] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.474936 15878 raft_consensus.cc:493] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.475096 15878 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.476141 15878 raft_consensus.cc:515] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10f7a8de53714ceea0e1c6731e809fe6" member_type: VOTER }
I20260812 06:18:36.476692 15878 leader_election.cc:304] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [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: 10f7a8de53714ceea0e1c6731e809fe6; no voters: 
I20260812 06:18:36.477082 15878 leader_election.cc:290] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.477308 15882 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.477602 15882 raft_consensus.cc:697] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 1 LEADER]: Becoming Leader. State: Replica: 10f7a8de53714ceea0e1c6731e809fe6, State: Running, Role: LEADER
I20260812 06:18:36.478039 15882 consensus_queue.cc:237] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [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: "10f7a8de53714ceea0e1c6731e809fe6" member_type: VOTER }
I20260812 06:18:36.478307 15878 sys_catalog.cc:565] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:36.480417 15884 sys_catalog.cc:455] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 10f7a8de53714ceea0e1c6731e809fe6. Latest consensus state: current_term: 1 leader_uuid: "10f7a8de53714ceea0e1c6731e809fe6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10f7a8de53714ceea0e1c6731e809fe6" member_type: VOTER } }
I20260812 06:18:36.480571 15884 sys_catalog.cc:458] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:36.480845 15883 sys_catalog.cc:455] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "10f7a8de53714ceea0e1c6731e809fe6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10f7a8de53714ceea0e1c6731e809fe6" member_type: VOTER } }
I20260812 06:18:36.480937 15883 sys_catalog.cc:458] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:36.481271 15892 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:36.481326 15805 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:36.484077 15892 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:36.489514 15892 catalog_manager.cc:1383] Generated new cluster ID: 6885ca8ac80f4abf9bc001a2f083b258
I20260812 06:18:36.489614 15892 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:36.513733 15892 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:36.514724 15892 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:36.525315 15892 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6: Generated new TSK 0
I20260812 06:18:36.526407 15892 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:36.547019 15805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:36.551009 15903 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.551162 15904 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:18:36.551354 15906 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.551499 15805 server_base.cc:1061] running on GCE node
I20260812 06:18:36.551679 15805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:36.551734 15805 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:36.551766 15805 hybrid_clock.cc:648] HybridClock initialized: now 1786515516551766 us; error 0 us; skew 500 ppm
I20260812 06:18:36.552825 15805 webserver.cc:533] Webserver started at http://127.15.111.65:35621/ using document root <none> and password file <none>
I20260812 06:18:36.553017 15805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:36.553081 15805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:36.553177 15805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:36.553669 15805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/instance:
uuid: "49aae9c802674195a6ae551884901f9a"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-dhph"
I20260812 06:18:36.555907 15805 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:36.557256 15913 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.557569 15805 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:36.557651 15805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root
uuid: "49aae9c802674195a6ae551884901f9a"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-dhph"
I20260812 06:18:36.557747 15805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.570389 15805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.571043 15805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.571681 15805 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:36.572682 15805 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:36.572745 15805 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.572831 15805 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:36.572876 15805 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.581488 15805 rpc_server.cc:307] RPC server started. Bound to: 127.15.111.65:35579
I20260812 06:18:36.581521 15989 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.111.65:35579 every 8 connection(s)
I20260812 06:18:36.597121 15990 heartbeater.cc:344] Connected to a master server at 127.15.111.126:37839
I20260812 06:18:36.597442 15990 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:36.598157 15990 heartbeater.cc:507] Master 127.15.111.126:37839 requested a full tablet report, sending...
I20260812 06:18:36.600198 15839 ts_manager.cc:194] Registered new tserver with Master: 49aae9c802674195a6ae551884901f9a (127.15.111.65:35579)
I20260812 06:18:36.600345 15805 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018041438s
I20260812 06:18:36.601862 15839 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46672
I20260812 06:18:36.615023 15839 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46684:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:36.632498 15947 tablet_service.cc:1511] Processing CreateTablet for tablet 4d64548883474844b829e8db4097bbc7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b0a6f5df47904dc5ac7da13e1c346caf]), partition=
I20260812 06:18:36.633004 15947 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4d64548883474844b829e8db4097bbc7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.635618 16006 tablet_bootstrap.cc:492] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Bootstrap starting.
I20260812 06:18:36.636734 16006 tablet_bootstrap.cc:654] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.638813 16006 tablet_bootstrap.cc:492] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: No bootstrap required, opened a new log
I20260812 06:18:36.638958 16006 ts_tablet_manager.cc:1403] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:36.639588 16006 raft_consensus.cc:359] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "49aae9c802674195a6ae551884901f9a" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 35579 } }
I20260812 06:18:36.639853 16006 raft_consensus.cc:385] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.639938 16006 raft_consensus.cc:740] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 49aae9c802674195a6ae551884901f9a, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.640130 16006 consensus_queue.cc:260] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [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: "49aae9c802674195a6ae551884901f9a" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 35579 } }
I20260812 06:18:36.640287 16006 raft_consensus.cc:399] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.640362 16006 raft_consensus.cc:493] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.640431 16006 raft_consensus.cc:3060] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.641361 16006 raft_consensus.cc:515] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "49aae9c802674195a6ae551884901f9a" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 35579 } }
I20260812 06:18:36.641553 16006 leader_election.cc:304] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [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: 49aae9c802674195a6ae551884901f9a; no voters: 
I20260812 06:18:36.641853 16006 leader_election.cc:290] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.641980 16008 raft_consensus.cc:2804] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.642284 16008 raft_consensus.cc:697] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 1 LEADER]: Becoming Leader. State: Replica: 49aae9c802674195a6ae551884901f9a, State: Running, Role: LEADER
I20260812 06:18:36.642325 16006 ts_tablet_manager.cc:1434] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:36.642513 16008 consensus_queue.cc:237] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [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: "49aae9c802674195a6ae551884901f9a" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 35579 } }
I20260812 06:18:36.642513 15990 heartbeater.cc:499] Master 127.15.111.126:37839 was elected leader, sending a full tablet report...
I20260812 06:18:36.647377 15839 catalog_manager.cc:5719] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a reported cstate change: term changed from 0 to 1, leader changed from <none> to 49aae9c802674195a6ae551884901f9a (127.15.111.65). New cstate: current_term: 1 leader_uuid: "49aae9c802674195a6ae551884901f9a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "49aae9c802674195a6ae551884901f9a" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 35579 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:36.718164 15805 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.020s	sys 0.008s
I20260812 06:18:36.832878 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushMRSOp(4d64548883474844b829e8db4097bbc7): perf score=15.086190
I20260812 06:18:36.989792 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushMRSOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.156s	user 0.118s	sys 0.033s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":309,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1126,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":30861,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":101248,"thread_start_us":155,"threads_started":1,"update_count":1050}
I20260812 06:18:36.991173 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling LogGCOp(4d64548883474844b829e8db4097bbc7): free 8725963 bytes of WAL
I20260812 06:18:36.991515 15919 log_reader.cc:385] T 4d64548883474844b829e8db4097bbc7: removed 1 log segments from log reader
I20260812 06:18:36.991586 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000001 (ops 1-6)
I20260812 06:18:36.994182 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: LogGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:36.994623 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7): 12308958 bytes on disk
I20260812 06:18:36.995332 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.995786 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:37.011224 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5907,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.013084 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:37.139816 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2427,"lbm_read_time_us":8244,"lbm_reads_lt_1ms":360,"lbm_write_time_us":22321,"lbm_writes_lt_1ms":343,"mutex_wait_us":287,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":378,"threads_started":5,"update_count":1500}
I20260812 06:18:37.140367 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=10.126437
I20260812 06:18:37.190318 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.050s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.190994 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:37.201694 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.202230 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:37.329231 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.127s	user 0.115s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":450,"lbm_read_time_us":8766,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23727,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.329859 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=10.126437
I20260812 06:18:37.388842 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.059s	user 0.038s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19815,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.389513 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:37.402117 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.402987 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:37.563122 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.160s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":10835,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24462,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":54400,"update_count":2000}
I20260812 06:18:37.564136 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=10.126437
I20260812 06:18:37.615851 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.051s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18164,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.616400 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:37.631582 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.632565 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:37.779351 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.146s	user 0.110s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":11020,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27297,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:37.779963 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=10.126437
I20260812 06:18:37.837188 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.057s	user 0.026s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20994,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.837728 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:37.859193 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.021s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.859865 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:37.994897 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.135s	user 0.114s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":381,"lbm_read_time_us":7697,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26879,"lbm_writes_lt_1ms":443,"mutex_wait_us":113,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:18:37.995488 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=11.118625
I20260812 06:18:38.050433 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.055s	user 0.027s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20106,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:38.051556 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:38.070075 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7107,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.070847 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:38.234926 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.164s	user 0.113s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":8630,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29250,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:38.235723 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=11.118625
I20260812 06:18:38.280897 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19936,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:38.281562 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:38.296730 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5882,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.297231 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:38.440246 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.143s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":421,"lbm_read_time_us":9015,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29192,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:38.441200 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=10.126437
I20260812 06:18:38.490483 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.049s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22514,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.491129 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:38.503204 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.503760 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushMRSOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:38.543015 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushMRSOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.039s	user 0.039s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":130,"dirs.run_cpu_time_us":354,"dirs.run_wall_time_us":1682,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2106,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:38.544015 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling LogGCOp(4d64548883474844b829e8db4097bbc7): free 133024358 bytes of WAL
I20260812 06:18:38.544390 15919 log_reader.cc:385] T 4d64548883474844b829e8db4097bbc7: removed 13 log segments from log reader
I20260812 06:18:38.544472 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000002 (ops 7-11)
I20260812 06:18:38.544523 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000003 (ops 12-16)
I20260812 06:18:38.544567 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000004 (ops 17-21)
I20260812 06:18:38.544600 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000005 (ops 22-26)
I20260812 06:18:38.544642 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000006 (ops 27-31)
I20260812 06:18:38.544674 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000007 (ops 32-36)
I20260812 06:18:38.544714 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000008 (ops 37-40)
I20260812 06:18:38.544754 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000009 (ops 41-45)
I20260812 06:18:38.544786 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000010 (ops 46-50)
I20260812 06:18:38.544817 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000011 (ops 51-55)
I20260812 06:18:38.544868 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000012 (ops 56-60)
I20260812 06:18:38.544925 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000013 (ops 61-65)
I20260812 06:18:38.544963 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000014 (ops 66-70)
I20260812 06:18:38.575717 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: LogGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:38.576213 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=6.157687
I20260812 06:18:38.601317 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.025s	user 0.002s	sys 0.020s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10669,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:38.601990 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7): 482 bytes on disk
I20260812 06:18:38.602662 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":133,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.603407 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:38.801157 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.198s	user 0.153s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":160,"lbm_read_time_us":14108,"lbm_reads_lt_1ms":669,"lbm_write_time_us":39371,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:38.801862 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=14.095187
I20260812 06:18:38.867997 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.066s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.868580 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:38.881181 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.881862 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:39.053723 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.172s	user 0.129s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":10854,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37126,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":80384,"update_count":2500}
I20260812 06:18:39.054399 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=14.095187
I20260812 06:18:39.112376 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.058s	user 0.039s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28245,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.112980 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:39.128191 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.128733 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:39.301702 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.172s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":10109,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34466,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:39.302439 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=14.095187
I20260812 06:18:39.377915 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.075s	user 0.041s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.378676 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:39.396700 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.397264 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:39.599669 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.202s	user 0.123s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1087,"lbm_read_time_us":13439,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33085,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:39.600368 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=14.095187
I20260812 06:18:39.663856 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.063s	user 0.043s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27679,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.664546 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:39.845736 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.181s	user 0.110s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":594,"lbm_read_time_us":10631,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27669,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:39.846463 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=14.095187
I20260812 06:18:39.904819 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.058s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22615,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.905319 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:39.918838 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.919449 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:40.143793 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.224s	user 0.146s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1141,"lbm_read_time_us":12611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37437,"lbm_writes_lt_1ms":543,"mutex_wait_us":355,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":54400,"update_count":2500}
I20260812 06:18:40.144881 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=14.095187
I20260812 06:18:40.208809 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.064s	user 0.044s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27109,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.210202 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:40.224579 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.225095 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushMRSOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:40.260793 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushMRSOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1671,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1882,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:40.261613 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling LogGCOp(4d64548883474844b829e8db4097bbc7): free 132118273 bytes of WAL
I20260812 06:18:40.261855 15919 log_reader.cc:385] T 4d64548883474844b829e8db4097bbc7: removed 13 log segments from log reader
I20260812 06:18:40.261897 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000015 (ops 71-74)
I20260812 06:18:40.261927 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000016 (ops 75-79)
I20260812 06:18:40.261988 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000017 (ops 80-84)
I20260812 06:18:40.262022 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000018 (ops 85-89)
I20260812 06:18:40.262063 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000019 (ops 90-94)
I20260812 06:18:40.262089 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000020 (ops 95-98)
I20260812 06:18:40.262126 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000021 (ops 99-103)
I20260812 06:18:40.262153 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000022 (ops 104-108)
I20260812 06:18:40.262193 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000023 (ops 109-113)
I20260812 06:18:40.262218 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000024 (ops 114-118)
I20260812 06:18:40.262259 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000025 (ops 119-123)
I20260812 06:18:40.262285 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000026 (ops 124-128)
I20260812 06:18:40.262321 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000027 (ops 129-132)
I20260812 06:18:40.296576 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: LogGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:18:40.297297 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=3.181125
I20260812 06:18:40.316181 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.019s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6125,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:40.316846 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:40.333393 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5909,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.334197 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:40.622843 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.288s	user 0.177s	sys 0.107s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938774,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":879,"lbm_read_time_us":21583,"lbm_reads_lt_1ms":774,"lbm_write_time_us":47342,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":27648,"thread_start_us":113,"threads_started":1,"update_count":3500}
I20260812 06:18:40.623631 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7): 483 bytes on disk
I20260812 06:18:40.624970 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.625766 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=16.079562
I20260812 06:18:40.703366 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.077s	user 0.059s	sys 0.011s Metrics: {"bytes_written":18050868,"delete_count":0,"lbm_write_time_us":30465,"lbm_writes_lt_1ms":443,"reinsert_count":0,"update_count":2200}
I20260812 06:18:40.704609 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=5.165500
I20260812 06:18:40.735756 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.031s	user 0.022s	sys 0.008s Metrics: {"bytes_written":6564117,"delete_count":0,"lbm_write_time_us":12445,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:18:40.736481 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:40.961174 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.224s	user 0.149s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836142,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1560,"lbm_read_time_us":17045,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39907,"lbm_writes_lt_1ms":643,"mutex_wait_us":496,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:18:40.962323 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=16.079562
I20260812 06:18:41.053511 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.091s	user 0.027s	sys 0.043s Metrics: {"bytes_written":18420085,"delete_count":0,"lbm_write_time_us":32810,"lbm_writes_lt_1ms":452,"reinsert_count":0,"update_count":2245}
I20260812 06:18:41.054106 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=4.173312
I20260812 06:18:41.073915 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":6194903,"delete_count":0,"lbm_write_time_us":7517,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:18:41.074939 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:41.315857 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.241s	user 0.163s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836145,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":15231,"lbm_reads_lt_1ms":672,"lbm_write_time_us":41970,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":3000}
I20260812 06:18:41.316524 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=16.079562
I20260812 06:18:41.377812 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.061s	user 0.025s	sys 0.029s Metrics: {"bytes_written":18338035,"delete_count":0,"lbm_write_time_us":25899,"lbm_writes_lt_1ms":450,"reinsert_count":0,"update_count":2235}
I20260812 06:18:41.378516 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=1.196750
I20260812 06:18:41.388770 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2789863,"delete_count":0,"lbm_write_time_us":3580,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:18:41.389276 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:41.405860 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":5949,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:18:41.406898 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:41.625902 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.219s	user 0.147s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":714,"lbm_read_time_us":15096,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35976,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":3000}
I20260812 06:18:41.626788 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=16.079562
I20260812 06:18:41.709910 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.083s	user 0.037s	sys 0.025s Metrics: {"bytes_written":17927796,"delete_count":0,"lbm_write_time_us":29080,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":439,"reinsert_count":0,"update_count":2185}
I20260812 06:18:41.710480 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=5.165500
I20260812 06:18:41.737967 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.027s	user 0.010s	sys 0.009s Metrics: {"bytes_written":6687192,"delete_count":0,"lbm_write_time_us":9138,"lbm_writes_lt_1ms":166,"reinsert_count":0,"update_count":815}
I20260812 06:18:41.738492 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:42.000385 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.262s	user 0.155s	sys 0.097s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836145,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":333,"lbm_read_time_us":17408,"lbm_reads_lt_1ms":664,"lbm_write_time_us":42115,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":3000}
I20260812 06:18:42.001119 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=18.063937
I20260812 06:18:42.083181 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.082s	user 0.047s	sys 0.023s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":31621,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:18:42.083835 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=2.188937
I20260812 06:18:42.096047 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4489,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.096988 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushMRSOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:42.137707 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushMRSOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.041s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":464,"dirs.run_wall_time_us":2400,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2513,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:42.138640 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling LogGCOp(4d64548883474844b829e8db4097bbc7): free 129773875 bytes of WAL
I20260812 06:18:42.138957 15919 log_reader.cc:385] T 4d64548883474844b829e8db4097bbc7: removed 13 log segments from log reader
I20260812 06:18:42.139030 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000028 (ops 133-137)
I20260812 06:18:42.139092 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000029 (ops 138-142)
I20260812 06:18:42.139120 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000030 (ops 143-147)
I20260812 06:18:42.139153 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000031 (ops 148-152)
I20260812 06:18:42.139184 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000032 (ops 153-157)
I20260812 06:18:42.139209 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000033 (ops 158-162)
I20260812 06:18:42.139236 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000034 (ops 163-167)
I20260812 06:18:42.139264 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000035 (ops 168-172)
I20260812 06:18:42.139302 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000036 (ops 173-177)
I20260812 06:18:42.139333 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000037 (ops 178-182)
I20260812 06:18:42.139370 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000038 (ops 183-186)
I20260812 06:18:42.139415 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000039 (ops 187-191)
I20260812 06:18:42.139472 15919 log.cc:1079] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/4d64548883474844b829e8db4097bbc7/wal-000000040 (ops 192-196)
I20260812 06:18:42.177201 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: LogGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.038s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:18:42.177734 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7): perf score=6.157687
I20260812 06:18:42.202260 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: FlushDeltaMemStoresOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.024s	user 0.008s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9909,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:42.202908 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7): 493 bytes on disk
I20260812 06:18:42.203630 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: UndoDeltaBlockGCOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.204263 15991 maintenance_manager.cc:419] P 49aae9c802674195a6ae551884901f9a: Scheduling MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7): perf score=1.000000
I20260812 06:18:42.226843 15805 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.508s	user 2.051s	sys 0.156s
I20260812 06:18:42.335480 15805 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.108s	user 0.005s	sys 0.000s
I20260812 06:18:42.336355 15805 tablet_server.cc:179] TabletServer@127.15.111.65:0 shutting down...
I20260812 06:18:42.426504 15919 maintenance_manager.cc:643] P 49aae9c802674195a6ae551884901f9a: MajorDeltaCompactionOp(4d64548883474844b829e8db4097bbc7) complete. Timing: real 0.222s	user 0.133s	sys 0.089s Metrics: {"cfile_cache_miss":833,"cfile_cache_miss_bytes":37041083,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":436,"lbm_read_time_us":15866,"lbm_reads_lt_1ms":865,"lbm_write_time_us":43063,"lbm_writes_lt_1ms":843,"mutex_wait_us":58,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":115840,"thread_start_us":97,"threads_started":1,"update_count":4000}
I20260812 06:18:42.427284 15805 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:42.427819 15805 tablet_replica.cc:333] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a: stopping tablet replica
I20260812 06:18:42.428086 15805 raft_consensus.cc:2243] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.428355 15805 raft_consensus.cc:2272] T 4d64548883474844b829e8db4097bbc7 P 49aae9c802674195a6ae551884901f9a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.448295 15805 tablet_server.cc:196] TabletServer@127.15.111.65:0 shutdown complete.
I20260812 06:18:42.500267 15805 master.cc:562] Master@127.15.111.126:37839 shutting down...
I20260812 06:18:42.505550 15805 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:42.505776 15805 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:42.505862 15805 tablet_replica.cc:333] T 00000000000000000000000000000000 P 10f7a8de53714ceea0e1c6731e809fe6: stopping tablet replica
I20260812 06:18:42.519074 15805 master.cc:584] Master@127.15.111.126:37839 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6233 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:42.609848 15805 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.111.126:41651
I20260812 06:18:42.610718 15805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:42.614005 15805 server_base.cc:1061] running on GCE node
W20260812 06:18:42.614326 16026 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.614357 16027 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:18:42.614357 16030 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.615032 15805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.615113 15805 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.615154 15805 hybrid_clock.cc:648] HybridClock initialized: now 1786515522615153 us; error 0 us; skew 500 ppm
I20260812 06:18:42.616195 15805 webserver.cc:533] Webserver started at http://127.15.111.126:43127/ using document root <none> and password file <none>
I20260812 06:18:42.616413 15805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.616492 15805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.616581 15805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.617030 15805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/master-0-root/instance:
uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-dhph"
I20260812 06:18:42.619050 15805 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:42.620247 16035 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.620697 15805 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:42.620796 15805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/master-0-root
uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-dhph"
I20260812 06:18:42.620900 15805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.638455 15805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.639003 15805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.643585 15805 rpc_server.cc:307] RPC server started. Bound to: 127.15.111.126:41651
I20260812 06:18:42.643813 16096 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.111.126:41651 every 8 connection(s)
I20260812 06:18:42.650813 16097 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.662897 16097 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee: Bootstrap starting.
I20260812 06:18:42.664054 16097 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.665350 16097 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee: No bootstrap required, opened a new log
I20260812 06:18:42.665899 16097 raft_consensus.cc:359] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee" member_type: VOTER }
I20260812 06:18:42.666029 16097 raft_consensus.cc:385] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.666082 16097 raft_consensus.cc:740] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a2c5b4cfcac74b4b9f4bca68da1621ee, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.666290 16097 consensus_queue.cc:260] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [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: "a2c5b4cfcac74b4b9f4bca68da1621ee" member_type: VOTER }
I20260812 06:18:42.666409 16097 raft_consensus.cc:399] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.666466 16097 raft_consensus.cc:493] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.666527 16097 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.667409 16097 raft_consensus.cc:515] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee" member_type: VOTER }
I20260812 06:18:42.667580 16097 leader_election.cc:304] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [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: a2c5b4cfcac74b4b9f4bca68da1621ee; no voters: 
I20260812 06:18:42.667829 16097 leader_election.cc:290] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.668025 16100 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.668246 16100 raft_consensus.cc:697] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 1 LEADER]: Becoming Leader. State: Replica: a2c5b4cfcac74b4b9f4bca68da1621ee, State: Running, Role: LEADER
I20260812 06:18:42.668395 16097 sys_catalog.cc:565] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:42.668406 16100 consensus_queue.cc:237] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [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: "a2c5b4cfcac74b4b9f4bca68da1621ee" member_type: VOTER }
I20260812 06:18:42.668951 16101 sys_catalog.cc:455] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee" member_type: VOTER } }
I20260812 06:18:42.669003 16102 sys_catalog.cc:455] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [sys.catalog]: SysCatalogTable state changed. Reason: New leader a2c5b4cfcac74b4b9f4bca68da1621ee. Latest consensus state: current_term: 1 leader_uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2c5b4cfcac74b4b9f4bca68da1621ee" member_type: VOTER } }
I20260812 06:18:42.669057 16101 sys_catalog.cc:458] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.669090 16102 sys_catalog.cc:458] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.669418 16107 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:42.671247 16107 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:42.671492 15805 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:42.674284 16107 catalog_manager.cc:1383] Generated new cluster ID: 3cf556f412274b91aca5ccbe6078f442
I20260812 06:18:42.674392 16107 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:42.693743 16107 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:42.694463 16107 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:42.703509 16107 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee: Generated new TSK 0
I20260812 06:18:42.703758 16107 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:42.736526 15805 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:42.739082 15805 server_base.cc:1061] running on GCE node
W20260812 06:18:42.739113 16121 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.739085 16124 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:18:42.739114 16122 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.739638 15805 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.739698 15805 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.739723 15805 hybrid_clock.cc:648] HybridClock initialized: now 1786515522739723 us; error 0 us; skew 500 ppm
I20260812 06:18:42.740684 15805 webserver.cc:533] Webserver started at http://127.15.111.65:44833/ using document root <none> and password file <none>
I20260812 06:18:42.740934 15805 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.741007 15805 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.741093 15805 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.741546 15805 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/instance:
uuid: "7951904ce57842cbb7688839741261eb"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-dhph"
I20260812 06:18:42.743425 15805 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:42.744787 16129 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.745108 15805 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:42.745260 15805 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root
uuid: "7951904ce57842cbb7688839741261eb"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-dhph"
I20260812 06:18:42.745354 15805 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.758019 15805 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.758498 15805 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.758919 15805 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:42.759445 15805 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:42.759505 15805 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.759567 15805 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:42.759632 15805 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.764926 15805 rpc_server.cc:307] RPC server started. Bound to: 127.15.111.65:33513
I20260812 06:18:42.764999 16198 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.111.65:33513 every 8 connection(s)
I20260812 06:18:42.775630 16199 heartbeater.cc:344] Connected to a master server at 127.15.111.126:41651
I20260812 06:18:42.775903 16199 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:42.776206 16199 heartbeater.cc:507] Master 127.15.111.126:41651 requested a full tablet report, sending...
I20260812 06:18:42.776979 16054 ts_manager.cc:194] Registered new tserver with Master: 7951904ce57842cbb7688839741261eb (127.15.111.65:33513)
I20260812 06:18:42.777801 16054 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51986
I20260812 06:18:42.778100 15805 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012670238s
I20260812 06:18:42.787678 16054 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52002:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:42.798636 16158 tablet_service.cc:1511] Processing CreateTablet for tablet 57db06a76f5f40f39eb973deda978813 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1da049a9c41a40e8826f6819350b00fa]), partition=
I20260812 06:18:42.798974 16158 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 57db06a76f5f40f39eb973deda978813. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.801402 16212 tablet_bootstrap.cc:492] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Bootstrap starting.
I20260812 06:18:42.802443 16212 tablet_bootstrap.cc:654] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.803817 16212 tablet_bootstrap.cc:492] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: No bootstrap required, opened a new log
I20260812 06:18:42.803962 16212 ts_tablet_manager.cc:1403] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:42.804581 16212 raft_consensus.cc:359] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7951904ce57842cbb7688839741261eb" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 33513 } }
I20260812 06:18:42.804713 16212 raft_consensus.cc:385] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.804844 16212 raft_consensus.cc:740] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7951904ce57842cbb7688839741261eb, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.805068 16212 consensus_queue.cc:260] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [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: "7951904ce57842cbb7688839741261eb" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 33513 } }
I20260812 06:18:42.805305 16212 raft_consensus.cc:399] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.805382 16212 raft_consensus.cc:493] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.805454 16212 raft_consensus.cc:3060] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.806429 16212 raft_consensus.cc:515] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7951904ce57842cbb7688839741261eb" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 33513 } }
I20260812 06:18:42.806632 16212 leader_election.cc:304] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [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: 7951904ce57842cbb7688839741261eb; no voters: 
I20260812 06:18:42.806991 16212 leader_election.cc:290] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.807159 16214 raft_consensus.cc:2804] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.807435 16214 raft_consensus.cc:697] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 1 LEADER]: Becoming Leader. State: Replica: 7951904ce57842cbb7688839741261eb, State: Running, Role: LEADER
I20260812 06:18:42.807461 16199 heartbeater.cc:499] Master 127.15.111.126:41651 was elected leader, sending a full tablet report...
I20260812 06:18:42.807468 16212 ts_tablet_manager.cc:1434] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:42.807613 16214 consensus_queue.cc:237] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [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: "7951904ce57842cbb7688839741261eb" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 33513 } }
I20260812 06:18:42.809466 16054 catalog_manager.cc:5719] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb reported cstate change: term changed from 0 to 1, leader changed from <none> to 7951904ce57842cbb7688839741261eb (127.15.111.65). New cstate: current_term: 1 leader_uuid: "7951904ce57842cbb7688839741261eb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7951904ce57842cbb7688839741261eb" member_type: VOTER last_known_addr { host: "127.15.111.65" port: 33513 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:42.878931 15805 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.018s	sys 0.008s
I20260812 06:18:43.016147 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushMRSOp(57db06a76f5f40f39eb973deda978813): perf score=15.086190
I20260812 06:18:43.187610 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushMRSOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.171s	user 0.127s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":327,"dirs.run_wall_time_us":1079,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40513,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:18:43.188324 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling LogGCOp(57db06a76f5f40f39eb973deda978813): free 11976772 bytes of WAL
I20260812 06:18:43.188546 16134 log_reader.cc:385] T 57db06a76f5f40f39eb973deda978813: removed 1 log segments from log reader
I20260812 06:18:43.188591 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000001 (ops 1-6)
I20260812 06:18:43.191874 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: LogGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:43.192382 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:43.206187 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.206737 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:43.352427 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.146s	user 0.105s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":64,"lbm_read_time_us":10333,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27757,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":668,"threads_started":5,"update_count":2000}
I20260812 06:18:43.353350 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813): 12308959 bytes on disk
I20260812 06:18:43.354009 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.354728 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:43.402160 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.047s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.402720 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:43.413872 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.414489 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:43.566164 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.151s	user 0.118s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":10881,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29115,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":2000}
I20260812 06:18:43.566915 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:43.629109 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.062s	user 0.024s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19082,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.629738 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:43.640749 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.641224 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:43.805601 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.164s	user 0.115s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1163,"lbm_read_time_us":12240,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24084,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":34176,"update_count":2000}
I20260812 06:18:43.806309 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:43.856032 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.050s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17758,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.856681 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:43.869040 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.869752 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:44.000614 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.131s	user 0.117s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":684,"lbm_read_time_us":10297,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22871,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":48512,"update_count":2000}
I20260812 06:18:44.002269 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:44.046103 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.046758 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:44.058393 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.058910 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:44.193826 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.135s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":408,"lbm_read_time_us":10053,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23938,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26752,"update_count":2000}
I20260812 06:18:44.194432 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:44.249352 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.055s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17133,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.250054 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:44.262287 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.262794 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:44.430266 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.167s	user 0.125s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":353,"lbm_read_time_us":13538,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26460,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.430990 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:44.478163 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.047s	user 0.034s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20372,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.478785 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:44.491010 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.491956 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushMRSOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:44.524998 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushMRSOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1630,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2086,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:44.525795 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling LogGCOp(57db06a76f5f40f39eb973deda978813): free 112692305 bytes of WAL
I20260812 06:18:44.526082 16134 log_reader.cc:385] T 57db06a76f5f40f39eb973deda978813: removed 11 log segments from log reader
I20260812 06:18:44.526144 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000002 (ops 7-11)
I20260812 06:18:44.526196 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000003 (ops 12-16)
I20260812 06:18:44.526250 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000004 (ops 17-21)
I20260812 06:18:44.526293 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000005 (ops 22-26)
I20260812 06:18:44.526341 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000006 (ops 27-31)
I20260812 06:18:44.526387 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000007 (ops 32-36)
I20260812 06:18:44.526427 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000008 (ops 37-41)
I20260812 06:18:44.526467 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000009 (ops 42-46)
I20260812 06:18:44.526504 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000010 (ops 47-51)
I20260812 06:18:44.526543 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000011 (ops 52-56)
I20260812 06:18:44.526605 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000012 (ops 57-61)
I20260812 06:18:44.555275 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: LogGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.029s	user 0.001s	sys 0.028s Metrics: {}
I20260812 06:18:44.555702 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:44.580950 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.025s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.581483 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling LogGCOp(57db06a76f5f40f39eb973deda978813): free 12017983 bytes of WAL
I20260812 06:18:44.581692 16134 log_reader.cc:385] T 57db06a76f5f40f39eb973deda978813: removed 1 log segments from log reader
I20260812 06:18:44.581734 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000013 (ops 62-66)
I20260812 06:18:44.584100 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: LogGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:44.584435 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813): 447 bytes on disk
I20260812 06:18:44.584856 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.585292 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:44.596220 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.601101 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:44.841454 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.240s	user 0.161s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":666,"lbm_read_time_us":17046,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37346,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29696,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:44.841979 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=14.095187
I20260812 06:18:44.906325 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.064s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23311,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.907188 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:44.919019 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.919502 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:45.124233 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.205s	user 0.142s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":516,"lbm_read_time_us":13905,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33997,"lbm_writes_lt_1ms":543,"mutex_wait_us":107,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:18:45.124835 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=14.095187
I20260812 06:18:45.192507 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.067s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24581,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.193404 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:45.218962 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.025s	user 0.006s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.219599 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:45.418984 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.199s	user 0.136s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":13209,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32127,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":153600,"update_count":2500}
I20260812 06:18:45.419821 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=14.095187
I20260812 06:18:45.477720 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.058s	user 0.025s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26415,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.478360 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:45.492309 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.492781 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:45.677450 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.184s	user 0.120s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":11823,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27182,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:45.678399 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=11.118625
I20260812 06:18:45.723201 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.044s	user 0.035s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18724,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.723834 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:45.745301 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.021s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.745839 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:45.756935 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.757490 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:45.923049 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.165s	user 0.137s	sys 0.026s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":840,"lbm_read_time_us":9840,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34148,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:45.923656 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:45.972771 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.049s	user 0.037s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20967,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.973418 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:45.993994 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.020s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.994508 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:46.137426 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.143s	user 0.100s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":9096,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29482,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:18:46.138226 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:46.199955 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.061s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22316,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.200525 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:46.214809 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.215405 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushMRSOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:46.247394 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushMRSOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1578,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:46.248060 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling LogGCOp(57db06a76f5f40f39eb973deda978813): free 121006432 bytes of WAL
I20260812 06:18:46.248292 16134 log_reader.cc:385] T 57db06a76f5f40f39eb973deda978813: removed 12 log segments from log reader
I20260812 06:18:46.248337 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000014 (ops 67-71)
I20260812 06:18:46.248366 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000015 (ops 72-76)
I20260812 06:18:46.248430 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000016 (ops 77-81)
I20260812 06:18:46.248476 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000017 (ops 82-86)
I20260812 06:18:46.248517 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000018 (ops 87-91)
I20260812 06:18:46.248554 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000019 (ops 92-96)
I20260812 06:18:46.248591 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000020 (ops 97-101)
I20260812 06:18:46.248628 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000021 (ops 102-106)
I20260812 06:18:46.248665 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000022 (ops 107-110)
I20260812 06:18:46.248703 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000023 (ops 111-115)
I20260812 06:18:46.248739 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000024 (ops 116-120)
I20260812 06:18:46.248786 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000025 (ops 121-125)
I20260812 06:18:46.277127 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: LogGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:46.277700 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=3.181125
I20260812 06:18:46.292476 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5892,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.293121 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813): 473 bytes on disk
I20260812 06:18:46.293740 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.294359 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:46.311290 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6134,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.311995 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:46.492616 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.180s	user 0.143s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":432,"lbm_read_time_us":12782,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35499,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20096,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:18:46.493592 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=14.095187
I20260812 06:18:46.544010 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.050s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.544669 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:46.562222 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.562844 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:46.747437 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.184s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":427,"lbm_read_time_us":13415,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34926,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:18:46.749506 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=11.118625
I20260812 06:18:46.798211 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.048s	user 0.020s	sys 0.024s Metrics: {"bytes_written":13579242,"delete_count":0,"lbm_write_time_us":21330,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:18:46.799121 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=1.196750
I20260812 06:18:46.808820 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3555,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:46.809350 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:46.990559 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.181s	user 0.120s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631285,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":430,"lbm_read_time_us":11973,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29216,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:46.991298 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:47.038717 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.047s	user 0.021s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19595,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.039494 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:47.057422 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.058012 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:47.206660 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.148s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1254,"lbm_read_time_us":11162,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27000,"lbm_writes_lt_1ms":443,"mutex_wait_us":359,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:47.207391 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:47.245630 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.037s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15723,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.246230 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:47.261415 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.262008 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:47.400398 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.138s	user 0.117s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":295,"lbm_read_time_us":9084,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26368,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:18:47.401068 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:47.441756 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.040s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16031,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.442433 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:47.570855 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.128s	user 0.102s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":196,"lbm_read_time_us":7993,"lbm_reads_lt_1ms":363,"lbm_write_time_us":25421,"lbm_writes_lt_1ms":343,"mutex_wait_us":30,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":1500}
I20260812 06:18:47.571623 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:47.609407 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.038s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15710,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.610196 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:47.735922 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.126s	user 0.108s	sys 0.011s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1287,"lbm_read_time_us":8385,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22508,"lbm_writes_lt_1ms":343,"mutex_wait_us":525,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":1500}
I20260812 06:18:47.736598 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:47.783135 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.046s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20286,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.783634 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushMRSOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:47.831121 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushMRSOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.047s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":308,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":2848,"drs_written":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2953,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:47.832993 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=3.181125
I20260812 06:18:47.847901 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.015s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:47.848407 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling LogGCOp(57db06a76f5f40f39eb973deda978813): free 112239548 bytes of WAL
I20260812 06:18:47.848628 16134 log_reader.cc:385] T 57db06a76f5f40f39eb973deda978813: removed 11 log segments from log reader
I20260812 06:18:47.848687 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000026 (ops 126-130)
I20260812 06:18:47.848740 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000027 (ops 131-135)
I20260812 06:18:47.848810 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000028 (ops 136-140)
I20260812 06:18:47.848852 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000029 (ops 141-144)
I20260812 06:18:47.848892 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000030 (ops 145-149)
I20260812 06:18:47.848935 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000031 (ops 150-154)
I20260812 06:18:47.848974 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000032 (ops 155-159)
I20260812 06:18:47.849015 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000033 (ops 160-164)
I20260812 06:18:47.849056 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000034 (ops 165-169)
I20260812 06:18:47.849093 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000035 (ops 170-174)
I20260812 06:18:47.849133 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000036 (ops 175-179)
I20260812 06:18:47.883514 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: LogGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.035s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:47.884456 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:47.909936 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.025s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5761,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.910499 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling LogGCOp(57db06a76f5f40f39eb973deda978813): free 12017954 bytes of WAL
I20260812 06:18:47.910737 16134 log_reader.cc:385] T 57db06a76f5f40f39eb973deda978813: removed 1 log segments from log reader
I20260812 06:18:47.910777 16134 log.cc:1079] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: Deleting log segment in path: /tmp/dist-test-taskum92Np/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516364252-15805-0/minicluster-data/ts-0-root/wals/57db06a76f5f40f39eb973deda978813/wal-000000037 (ops 180-184)
I20260812 06:18:47.913065 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: LogGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:47.913432 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813): 462 bytes on disk
I20260812 06:18:47.913879 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: UndoDeltaBlockGCOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.914402 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:47.931334 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6790,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.931864 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:48.150921 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.218s	user 0.167s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3126,"lbm_read_time_us":17185,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38644,"lbm_writes_lt_1ms":643,"mutex_wait_us":3764,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":117,"threads_started":1,"update_count":3000}
I20260812 06:18:48.151573 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=14.095187
I20260812 06:18:48.224601 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.073s	user 0.051s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":35721,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.226462 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=2.188937
I20260812 06:18:48.244906 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.245770 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813): perf score=1.000000
I20260812 06:18:48.356298 15805 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.477s	user 2.091s	sys 0.157s
I20260812 06:18:48.404915 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: MajorDeltaCompactionOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.159s	user 0.137s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":425,"lbm_read_time_us":10118,"lbm_reads_lt_1ms":560,"lbm_write_time_us":32454,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.405506 16201 maintenance_manager.cc:419] P 7951904ce57842cbb7688839741261eb: Scheduling FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813): perf score=10.126437
I20260812 06:18:48.426928 15805 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.070s	user 0.003s	sys 0.000s
I20260812 06:18:48.429178 15805 tablet_server.cc:179] TabletServer@127.15.111.65:0 shutting down...
I20260812 06:18:48.449901 16134 maintenance_manager.cc:643] P 7951904ce57842cbb7688839741261eb: FlushDeltaMemStoresOp(57db06a76f5f40f39eb973deda978813) complete. Timing: real 0.044s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20326,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.450690 15805 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.450999 15805 tablet_replica.cc:333] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb: stopping tablet replica
I20260812 06:18:48.451146 15805 raft_consensus.cc:2243] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.451323 15805 raft_consensus.cc:2272] T 57db06a76f5f40f39eb973deda978813 P 7951904ce57842cbb7688839741261eb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.454800 15805 tablet_server.cc:196] TabletServer@127.15.111.65:0 shutdown complete.
I20260812 06:18:48.457777 15805 master.cc:562] Master@127.15.111.126:41651 shutting down...
I20260812 06:18:48.462723 15805 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.462926 15805 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.462975 15805 tablet_replica.cc:333] T 00000000000000000000000000000000 P a2c5b4cfcac74b4b9f4bca68da1621ee: stopping tablet replica
I20260812 06:18:48.476102 15805 master.cc:584] Master@127.15.111.126:41651 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5966 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12201 ms total)

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