[==========] 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:17.714862 16713 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.82.126:34645
I20260812 06:18:17.716219 16713 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:17.716985 16713 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:17.724135 16731 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:17.724191 16726 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:17.724517 16713 server_base.cc:1061] running on GCE node
W20260812 06:18:17.724571 16724 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.725185 16713 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:17.725335 16713 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:17.725378 16713 hybrid_clock.cc:648] HybridClock initialized: now 1786515497725376 us; error 0 us; skew 500 ppm
I20260812 06:18:17.727695 16713 webserver.cc:533] Webserver started at http://127.16.82.126:42471/ using document root <none> and password file <none>
I20260812 06:18:17.728369 16713 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:17.728432 16713 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:17.728696 16713 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:17.730746 16713 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/master-0-root/instance:
uuid: "0a6f27f922a54fc1be36858566a2d579"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-nfb5"
I20260812 06:18:17.735287 16713 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:18:17.737785 16739 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:17.739154 16713 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:17.739289 16713 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/master-0-root
uuid: "0a6f27f922a54fc1be36858566a2d579"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-nfb5"
I20260812 06:18:17.739410 16713 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-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:17.752770 16713 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:17.753515 16713 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:17.753710 16713 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:17.762585 16713 rpc_server.cc:307] RPC server started. Bound to: 127.16.82.126:34645
I20260812 06:18:17.762589 16823 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.82.126:34645 every 8 connection(s)
I20260812 06:18:17.765405 16824 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:17.771799 16824 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: Bootstrap starting.
I20260812 06:18:17.774542 16824 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:17.775658 16824 log.cc:826] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:17.777482 16824 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: No bootstrap required, opened a new log
I20260812 06:18:17.780520 16824 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a6f27f922a54fc1be36858566a2d579" member_type: VOTER }
I20260812 06:18:17.780706 16824 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:17.780768 16824 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0a6f27f922a54fc1be36858566a2d579, State: Initialized, Role: FOLLOWER
I20260812 06:18:17.781368 16824 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [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: "0a6f27f922a54fc1be36858566a2d579" member_type: VOTER }
I20260812 06:18:17.781513 16824 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:17.781561 16824 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:17.781656 16824 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:17.782385 16824 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a6f27f922a54fc1be36858566a2d579" member_type: VOTER }
I20260812 06:18:17.782815 16824 leader_election.cc:304] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [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: 0a6f27f922a54fc1be36858566a2d579; no voters: 
I20260812 06:18:17.783157 16824 leader_election.cc:290] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:17.783308 16829 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:17.783574 16829 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 1 LEADER]: Becoming Leader. State: Replica: 0a6f27f922a54fc1be36858566a2d579, State: Running, Role: LEADER
I20260812 06:18:17.784020 16829 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [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: "0a6f27f922a54fc1be36858566a2d579" member_type: VOTER }
I20260812 06:18:17.784267 16824 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:17.786099 16831 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0a6f27f922a54fc1be36858566a2d579. Latest consensus state: current_term: 1 leader_uuid: "0a6f27f922a54fc1be36858566a2d579" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a6f27f922a54fc1be36858566a2d579" member_type: VOTER } }
I20260812 06:18:17.786103 16830 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0a6f27f922a54fc1be36858566a2d579" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a6f27f922a54fc1be36858566a2d579" member_type: VOTER } }
I20260812 06:18:17.786244 16830 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:17.786242 16831 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:17.786969 16713 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:17.789223 16847 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:17.789309 16847 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:17.789376 16843 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:17.790138 16843 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:17.795908 16843 catalog_manager.cc:1383] Generated new cluster ID: c1f20c799440498387a7dd41d01d998e
I20260812 06:18:17.795979 16843 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:17.839570 16843 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:17.840655 16843 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:17.846532 16843 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: Generated new TSK 0
I20260812 06:18:17.847532 16843 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:17.852059 16713 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:17.855547 16853 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:17.855573 16852 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:17.855656 16855 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:17.855774 16713 server_base.cc:1061] running on GCE node
I20260812 06:18:17.856124 16713 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:17.856189 16713 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:17.856212 16713 hybrid_clock.cc:648] HybridClock initialized: now 1786515497856212 us; error 0 us; skew 500 ppm
I20260812 06:18:17.857303 16713 webserver.cc:533] Webserver started at http://127.16.82.65:32935/ using document root <none> and password file <none>
I20260812 06:18:17.857506 16713 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:17.857570 16713 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:17.857656 16713 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:17.858160 16713 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/instance:
uuid: "0f1a8fab42654f33b3cf89d0b94e301f"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-nfb5"
I20260812 06:18:17.860229 16713 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:17.861413 16863 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:17.861692 16713 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:17.861790 16713 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root
uuid: "0f1a8fab42654f33b3cf89d0b94e301f"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-nfb5"
I20260812 06:18:17.861881 16713 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-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:17.884581 16713 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:17.885149 16713 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:17.885809 16713 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:17.886998 16713 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:17.887076 16713 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.887159 16713 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:17.887198 16713 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.894380 16713 rpc_server.cc:307] RPC server started. Bound to: 127.16.82.65:36007
I20260812 06:18:17.894528 16968 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.82.65:36007 every 8 connection(s)
I20260812 06:18:17.909299 16969 heartbeater.cc:344] Connected to a master server at 127.16.82.126:34645
I20260812 06:18:17.909608 16969 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:17.910153 16969 heartbeater.cc:507] Master 127.16.82.126:34645 requested a full tablet report, sending...
I20260812 06:18:17.911821 16762 ts_manager.cc:194] Registered new tserver with Master: 0f1a8fab42654f33b3cf89d0b94e301f (127.16.82.65:36007)
I20260812 06:18:17.912031 16713 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016791147s
I20260812 06:18:17.913558 16762 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41532
I20260812 06:18:17.922602 16762 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41544:
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:17.937906 16911 tablet_service.cc:1511] Processing CreateTablet for tablet 3ea5626b42f44ba4aac3d491b64becbb (DEFAULT_TABLE table=heavy-update-compaction-test [id=e60096d9bf3e4d6a80d7792e2ebb6cc8]), partition=
I20260812 06:18:17.938521 16911 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3ea5626b42f44ba4aac3d491b64becbb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:17.941912 16986 tablet_bootstrap.cc:492] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Bootstrap starting.
I20260812 06:18:17.943312 16986 tablet_bootstrap.cc:654] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:17.944846 16986 tablet_bootstrap.cc:492] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: No bootstrap required, opened a new log
I20260812 06:18:17.944976 16986 ts_tablet_manager.cc:1403] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:17.945652 16986 raft_consensus.cc:359] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f1a8fab42654f33b3cf89d0b94e301f" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 36007 } }
I20260812 06:18:17.945785 16986 raft_consensus.cc:385] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:17.945835 16986 raft_consensus.cc:740] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0f1a8fab42654f33b3cf89d0b94e301f, State: Initialized, Role: FOLLOWER
I20260812 06:18:17.945989 16986 consensus_queue.cc:260] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [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: "0f1a8fab42654f33b3cf89d0b94e301f" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 36007 } }
I20260812 06:18:17.946106 16986 raft_consensus.cc:399] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:17.946157 16986 raft_consensus.cc:493] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:17.946213 16986 raft_consensus.cc:3060] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:17.947081 16986 raft_consensus.cc:515] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f1a8fab42654f33b3cf89d0b94e301f" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 36007 } }
I20260812 06:18:17.947257 16986 leader_election.cc:304] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [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: 0f1a8fab42654f33b3cf89d0b94e301f; no voters: 
I20260812 06:18:17.947500 16986 leader_election.cc:290] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:17.947618 16988 raft_consensus.cc:2804] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:17.947806 16988 raft_consensus.cc:697] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 1 LEADER]: Becoming Leader. State: Replica: 0f1a8fab42654f33b3cf89d0b94e301f, State: Running, Role: LEADER
I20260812 06:18:17.947919 16986 ts_tablet_manager.cc:1434] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:18:17.947954 16988 consensus_queue.cc:237] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [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: "0f1a8fab42654f33b3cf89d0b94e301f" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 36007 } }
I20260812 06:18:17.948382 16969 heartbeater.cc:499] Master 127.16.82.126:34645 was elected leader, sending a full tablet report...
I20260812 06:18:17.951794 16760 catalog_manager.cc:5719] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f reported cstate change: term changed from 0 to 1, leader changed from <none> to 0f1a8fab42654f33b3cf89d0b94e301f (127.16.82.65). New cstate: current_term: 1 leader_uuid: "0f1a8fab42654f33b3cf89d0b94e301f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f1a8fab42654f33b3cf89d0b94e301f" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 36007 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:18.018947 16713 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.012s	sys 0.013s
I20260812 06:18:18.145751 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=15.086190
I20260812 06:18:18.333413 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.187s	user 0.146s	sys 0.028s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":238,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1029,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44410,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":151,"threads_started":1,"update_count":1500}
I20260812 06:18:18.335198 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling LogGCOp(3ea5626b42f44ba4aac3d491b64becbb): free 8725963 bytes of WAL
I20260812 06:18:18.335614 16874 log_reader.cc:385] T 3ea5626b42f44ba4aac3d491b64becbb: removed 1 log segments from log reader
I20260812 06:18:18.335697 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000001 (ops 1-6)
I20260812 06:18:18.338330 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: LogGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:18.338797 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:18.358592 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.020s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.359310 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb): 12308958 bytes on disk
I20260812 06:18:18.360121 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.360725 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:18.515813 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.155s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1029,"lbm_read_time_us":11521,"lbm_reads_lt_1ms":460,"lbm_write_time_us":29368,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":393,"threads_started":5,"update_count":2000}
I20260812 06:18:18.516552 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:18.559127 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.042s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19127,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.559708 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:18.571892 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4580,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.572783 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:18.724386 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.151s	user 0.115s	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":337,"lbm_read_time_us":10233,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31187,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:18:18.725090 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:18.761528 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16016,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.762120 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:18.887128 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.125s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528780,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":180,"lbm_read_time_us":8577,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24196,"lbm_writes_lt_1ms":343,"mutex_wait_us":71,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:18.887773 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:18.932775 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.045s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19383,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.933337 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:19.055900 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.122s	user 0.094s	sys 0.025s 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":510,"lbm_read_time_us":8123,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23882,"lbm_writes_lt_1ms":343,"mutex_wait_us":240,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.056689 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:19.095768 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.039s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16999,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.096421 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:19.206884 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.110s	user 0.073s	sys 0.037s 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":1139,"lbm_read_time_us":7191,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21602,"lbm_writes_lt_1ms":343,"mutex_wait_us":52,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:19.207660 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:19.258849 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.051s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19575,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.259394 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:19.271503 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4595,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.272410 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:19.410969 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.138s	user 0.090s	sys 0.045s 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":465,"lbm_read_time_us":9054,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25953,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:19.411787 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:19.464075 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.052s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19558,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.464779 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:19.477113 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.477998 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:19.621524 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.143s	user 0.113s	sys 0.028s 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":378,"lbm_read_time_us":9978,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27452,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:19.622227 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:19.679873 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.057s	user 0.031s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20695,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.680573 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:19.699970 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.700662 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:19.733695 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":208,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1566,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1910,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:19.734887 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling LogGCOp(3ea5626b42f44ba4aac3d491b64becbb): free 124257178 bytes of WAL
I20260812 06:18:19.735193 16874 log_reader.cc:385] T 3ea5626b42f44ba4aac3d491b64becbb: removed 12 log segments from log reader
I20260812 06:18:19.735262 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000002 (ops 7-11)
I20260812 06:18:19.735319 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000003 (ops 12-16)
I20260812 06:18:19.735373 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000004 (ops 17-21)
I20260812 06:18:19.735415 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000005 (ops 22-26)
I20260812 06:18:19.735462 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000006 (ops 27-31)
I20260812 06:18:19.735498 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000007 (ops 32-36)
I20260812 06:18:19.735540 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000008 (ops 37-41)
I20260812 06:18:19.735576 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000009 (ops 42-46)
I20260812 06:18:19.735616 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000010 (ops 47-51)
I20260812 06:18:19.735654 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000011 (ops 52-56)
I20260812 06:18:19.735692 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000012 (ops 57-60)
I20260812 06:18:19.735729 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000013 (ops 61-65)
I20260812 06:18:19.763796 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: LogGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:19.764416 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb): 462 bytes on disk
I20260812 06:18:19.764928 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb) 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:19.765503 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:19.780699 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.015s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.781114 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:19.792802 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.793313 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:19.999415 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.206s	user 0.149s	sys 0.053s 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":769,"lbm_read_time_us":14594,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38773,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:18:20.000105 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=14.095187
I20260812 06:18:20.066494 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.066s	user 0.038s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28786,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.067081 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:20.081100 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.081662 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:20.262735 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.181s	user 0.144s	sys 0.035s 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":117,"lbm_read_time_us":12570,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31941,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:20.263854 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=12.110812
I20260812 06:18:20.333053 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.068s	user 0.042s	sys 0.023s Metrics: {"bytes_written":14235625,"delete_count":0,"lbm_write_time_us":32584,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":348,"reinsert_count":0,"update_count":1735}
I20260812 06:18:20.334000 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.196750
I20260812 06:18:20.349167 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2584733,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:18:20.349689 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:20.583329 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.233s	user 0.160s	sys 0.068s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21041521,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":575,"dirs.run_cpu_time_us":665,"dirs.run_wall_time_us":3846,"lbm_read_time_us":10907,"lbm_reads_lt_1ms":474,"lbm_write_time_us":38452,"lbm_writes_lt_1ms":453,"mutex_wait_us":220,"peak_mem_usage":51099678,"reinsert_count":0,"update_count":2050}
I20260812 06:18:20.584009 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=14.095187
I20260812 06:18:20.642383 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.058s	user 0.039s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25628,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.643483 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:20.670277 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.026s	user 0.014s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.671208 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:20.911844 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.240s	user 0.181s	sys 0.045s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24323469,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":964,"lbm_read_time_us":18343,"lbm_reads_lt_1ms":554,"lbm_write_time_us":37001,"lbm_writes_lt_1ms":533,"mutex_wait_us":332,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2450}
I20260812 06:18:20.912671 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=14.095187
I20260812 06:18:20.983496 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.071s	user 0.026s	sys 0.043s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":30730,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.984071 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:20.997269 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.997944 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:21.181535 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.183s	user 0.126s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":12634,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34940,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35840,"update_count":2500}
I20260812 06:18:21.182220 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=11.118625
I20260812 06:18:21.222157 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.040s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16798,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.223209 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:21.253948 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.029s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.254662 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:21.266459 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.267242 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:21.445487 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.178s	user 0.138s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733833,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":401,"lbm_read_time_us":13893,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34085,"lbm_writes_lt_1ms":543,"mutex_wait_us":102,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:21.446381 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=11.118625
I20260812 06:18:21.484190 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.038s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16106,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.484896 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:21.501084 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.016s	user 0.001s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5803,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.501747 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:21.546280 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.044s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":403,"dirs.run_wall_time_us":1470,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1931,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:21.547350 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb): 483 bytes on disk
I20260812 06:18:21.547804 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:21.548403 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=3.181125
I20260812 06:18:21.569235 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7844,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:21.569789 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling LogGCOp(3ea5626b42f44ba4aac3d491b64becbb): free 133024427 bytes of WAL
I20260812 06:18:21.570053 16874 log_reader.cc:385] T 3ea5626b42f44ba4aac3d491b64becbb: removed 13 log segments from log reader
I20260812 06:18:21.570102 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000014 (ops 66-70)
I20260812 06:18:21.570135 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000015 (ops 71-75)
I20260812 06:18:21.570205 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000016 (ops 76-80)
I20260812 06:18:21.570250 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000017 (ops 81-85)
I20260812 06:18:21.570295 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000018 (ops 86-90)
I20260812 06:18:21.570338 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000019 (ops 91-94)
I20260812 06:18:21.570403 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000020 (ops 95-99)
I20260812 06:18:21.570451 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000021 (ops 100-104)
I20260812 06:18:21.570487 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000022 (ops 105-109)
I20260812 06:18:21.570526 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000023 (ops 110-114)
I20260812 06:18:21.570567 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000024 (ops 115-119)
I20260812 06:18:21.570609 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000025 (ops 120-124)
I20260812 06:18:21.570652 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000026 (ops 125-129)
I20260812 06:18:21.600955 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: LogGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:21.601449 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:21.616925 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5488,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.617415 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:21.639824 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.022s	user 0.007s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.640812 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:21.898483 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.257s	user 0.177s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938888,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":6663,"dirs.run_cpu_time_us":445,"dirs.run_wall_time_us":3732,"lbm_read_time_us":18087,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44320,"lbm_writes_lt_1ms":743,"mutex_wait_us":4,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":181,"threads_started":1,"update_count":3500}
I20260812 06:18:21.899827 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=14.095187
I20260812 06:18:21.961901 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.062s	user 0.040s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22978,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.962771 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:21.980675 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.981406 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:22.181221 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.200s	user 0.146s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":11013,"lbm_reads_lt_1ms":568,"lbm_write_time_us":34497,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:18:22.182082 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=14.095187
I20260812 06:18:22.260876 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.079s	user 0.044s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28128,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.261611 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:22.275422 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.276160 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:22.475031 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.199s	user 0.142s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1641,"lbm_read_time_us":15266,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32316,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:22.476080 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:22.517164 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17700,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.518009 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:22.531754 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.532799 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:22.693068 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.160s	user 0.118s	sys 0.039s 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":938,"lbm_read_time_us":9931,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30974,"lbm_writes_lt_1ms":443,"mutex_wait_us":285,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:22.693706 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:22.744177 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.050s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.744827 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:22.757858 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4801,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.758414 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:22.908982 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.150s	user 0.110s	sys 0.040s 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":304,"lbm_read_time_us":11234,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29593,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":33280,"update_count":2000}
I20260812 06:18:22.909677 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=10.126437
I20260812 06:18:22.961035 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.051s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19669,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.961699 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:22.978852 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.979628 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:23.140971 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.161s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1146,"lbm_read_time_us":12103,"lbm_reads_lt_1ms":468,"lbm_write_time_us":31260,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":94848,"update_count":2000}
I20260812 06:18:23.142091 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=11.118625
I20260812 06:18:23.196053 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.054s	user 0.042s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19763,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:23.196769 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:23.209478 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4788,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.210163 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:23.243384 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushMRSOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1609,"drs_written":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1843,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:23.244385 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling LogGCOp(3ea5626b42f44ba4aac3d491b64becbb): free 112239554 bytes of WAL
I20260812 06:18:23.244665 16874 log_reader.cc:385] T 3ea5626b42f44ba4aac3d491b64becbb: removed 11 log segments from log reader
I20260812 06:18:23.244741 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000027 (ops 130-134)
I20260812 06:18:23.244807 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000028 (ops 135-139)
I20260812 06:18:23.244875 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000029 (ops 140-144)
I20260812 06:18:23.244925 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000030 (ops 145-148)
I20260812 06:18:23.244971 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000031 (ops 149-153)
I20260812 06:18:23.245016 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000032 (ops 154-158)
I20260812 06:18:23.245061 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000033 (ops 159-163)
I20260812 06:18:23.245106 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000034 (ops 164-168)
I20260812 06:18:23.245151 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000035 (ops 169-173)
I20260812 06:18:23.245196 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000036 (ops 174-178)
I20260812 06:18:23.245242 16874 log.cc:1079] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/3ea5626b42f44ba4aac3d491b64becbb/wal-000000037 (ops 179-183)
I20260812 06:18:23.269732 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: LogGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:23.270404 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:23.296813 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.026s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.297524 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb): 448 bytes on disk
I20260812 06:18:23.298056 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: UndoDeltaBlockGCOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.298708 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:23.311484 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.311969 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:23.555599 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.243s	user 0.160s	sys 0.083s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836366,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1095,"lbm_read_time_us":17099,"lbm_reads_lt_1ms":674,"lbm_write_time_us":44272,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":136,"threads_started":1,"update_count":3000}
I20260812 06:18:23.557682 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=14.095187
I20260812 06:18:23.620332 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.062s	user 0.041s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28628,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.621045 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=2.188937
I20260812 06:18:23.633181 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.633729 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=1.000000
I20260812 06:18:23.735543 16713 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.716s	user 2.094s	sys 0.113s
I20260812 06:18:23.813797 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: MajorDeltaCompactionOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.180s	user 0.120s	sys 0.059s 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":1197,"lbm_read_time_us":14005,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32683,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:18:23.814846 16972 maintenance_manager.cc:419] P 0f1a8fab42654f33b3cf89d0b94e301f: Scheduling FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb): perf score=6.157687
I20260812 06:18:23.820088 16713 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.004s	sys 0.000s
I20260812 06:18:23.821049 16713 tablet_server.cc:179] TabletServer@127.16.82.65:0 shutting down...
I20260812 06:18:23.847254 16874 maintenance_manager.cc:643] P 0f1a8fab42654f33b3cf89d0b94e301f: FlushDeltaMemStoresOp(3ea5626b42f44ba4aac3d491b64becbb) complete. Timing: real 0.032s	user 0.015s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12809,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:23.847997 16713 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:23.848457 16713 tablet_replica.cc:333] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f: stopping tablet replica
I20260812 06:18:23.848753 16713 raft_consensus.cc:2243] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:23.849046 16713 raft_consensus.cc:2272] T 3ea5626b42f44ba4aac3d491b64becbb P 0f1a8fab42654f33b3cf89d0b94e301f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:23.865161 16713 tablet_server.cc:196] TabletServer@127.16.82.65:0 shutdown complete.
I20260812 06:18:23.871163 16713 master.cc:562] Master@127.16.82.126:34645 shutting down...
I20260812 06:18:23.875284 16713 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:23.875504 16713 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:23.875595 16713 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0a6f27f922a54fc1be36858566a2d579: stopping tablet replica
I20260812 06:18:23.889309 16713 master.cc:584] Master@127.16.82.126:34645 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6270 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:23.997372 16713 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.82.126:44289
I20260812 06:18:23.997905 16713 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.001299 17014 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:24.001382 16713 server_base.cc:1061] running on GCE node
W20260812 06:18:24.001299 17015 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:24.001302 17018 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:24.001839 16713 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.001909 16713 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:24.001945 16713 hybrid_clock.cc:648] HybridClock initialized: now 1786515504001943 us; error 0 us; skew 500 ppm
I20260812 06:18:24.002869 16713 webserver.cc:533] Webserver started at http://127.16.82.126:46609/ using document root <none> and password file <none>
I20260812 06:18:24.003091 16713 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.003171 16713 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.003261 16713 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.003744 16713 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/master-0-root/instance:
uuid: "bcf602fbef884d15aafbd85b6ab1959a"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-nfb5"
I20260812 06:18:24.005517 16713 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:24.006520 17029 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:24.006788 16713 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:24.006883 16713 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/master-0-root
uuid: "bcf602fbef884d15aafbd85b6ab1959a"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-nfb5"
I20260812 06:18:24.007017 16713 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-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:24.017525 16713 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.017968 16713 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:24.022903 16713 rpc_server.cc:307] RPC server started. Bound to: 127.16.82.126:44289
I20260812 06:18:24.025264 17111 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:24.027002 17110 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.82.126:44289 every 8 connection(s)
I20260812 06:18:24.029630 17111 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a: Bootstrap starting.
I20260812 06:18:24.030521 17111 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:24.031649 17111 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a: No bootstrap required, opened a new log
I20260812 06:18:24.032092 17111 raft_consensus.cc:359] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcf602fbef884d15aafbd85b6ab1959a" member_type: VOTER }
I20260812 06:18:24.032250 17111 raft_consensus.cc:385] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:24.032320 17111 raft_consensus.cc:740] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bcf602fbef884d15aafbd85b6ab1959a, State: Initialized, Role: FOLLOWER
I20260812 06:18:24.032531 17111 consensus_queue.cc:260] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [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: "bcf602fbef884d15aafbd85b6ab1959a" member_type: VOTER }
I20260812 06:18:24.032646 17111 raft_consensus.cc:399] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:24.032693 17111 raft_consensus.cc:493] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:24.032750 17111 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:24.033483 17111 raft_consensus.cc:515] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcf602fbef884d15aafbd85b6ab1959a" member_type: VOTER }
I20260812 06:18:24.033643 17111 leader_election.cc:304] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [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: bcf602fbef884d15aafbd85b6ab1959a; no voters: 
I20260812 06:18:24.033844 17111 leader_election.cc:290] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:24.033968 17114 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:24.034192 17114 raft_consensus.cc:697] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 1 LEADER]: Becoming Leader. State: Replica: bcf602fbef884d15aafbd85b6ab1959a, State: Running, Role: LEADER
I20260812 06:18:24.034353 17114 consensus_queue.cc:237] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [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: "bcf602fbef884d15aafbd85b6ab1959a" member_type: VOTER }
I20260812 06:18:24.034370 17111 sys_catalog.cc:565] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:24.034852 17116 sys_catalog.cc:455] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [sys.catalog]: SysCatalogTable state changed. Reason: New leader bcf602fbef884d15aafbd85b6ab1959a. Latest consensus state: current_term: 1 leader_uuid: "bcf602fbef884d15aafbd85b6ab1959a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcf602fbef884d15aafbd85b6ab1959a" member_type: VOTER } }
I20260812 06:18:24.034960 17116 sys_catalog.cc:458] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:24.034830 17115 sys_catalog.cc:455] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bcf602fbef884d15aafbd85b6ab1959a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bcf602fbef884d15aafbd85b6ab1959a" member_type: VOTER } }
I20260812 06:18:24.035023 17115 sys_catalog.cc:458] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:24.035548 17118 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:24.036259 17118 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:24.036553 16713 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:24.037971 17118 catalog_manager.cc:1383] Generated new cluster ID: e7f893dbd54f40b1a3206360f5eed87a
I20260812 06:18:24.038028 17118 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:24.051648 17118 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:24.052282 17118 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:24.057263 17118 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a: Generated new TSK 0
I20260812 06:18:24.057441 17118 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:24.068890 16713 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.071126 17148 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:24.071179 16713 server_base.cc:1061] running on GCE node
W20260812 06:18:24.071231 17145 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:24.071141 17144 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:24.071480 16713 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.071521 16713 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:24.071538 16713 hybrid_clock.cc:648] HybridClock initialized: now 1786515504071538 us; error 0 us; skew 500 ppm
I20260812 06:18:24.072480 16713 webserver.cc:533] Webserver started at http://127.16.82.65:35031/ using document root <none> and password file <none>
I20260812 06:18:24.072657 16713 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.072702 16713 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.072762 16713 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.073153 16713 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/instance:
uuid: "a714cec1ea4a4cc5a59bd8101097ecb1"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-nfb5"
I20260812 06:18:24.074627 16713 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:24.075887 17155 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:24.076174 16713 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:24.076243 16713 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root
uuid: "a714cec1ea4a4cc5a59bd8101097ecb1"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-nfb5"
I20260812 06:18:24.076334 16713 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-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:24.083710 16713 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.084069 16713 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:24.084381 16713 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:24.084846 16713 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:24.084905 16713 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.084961 16713 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:24.085011 16713 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.089605 16713 rpc_server.cc:307] RPC server started. Bound to: 127.16.82.65:33121
I20260812 06:18:24.090458 17245 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.82.65:33121 every 8 connection(s)
I20260812 06:18:24.097733 17246 heartbeater.cc:344] Connected to a master server at 127.16.82.126:44289
I20260812 06:18:24.097860 17246 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:24.098116 17246 heartbeater.cc:507] Master 127.16.82.126:44289 requested a full tablet report, sending...
I20260812 06:18:24.098815 17051 ts_manager.cc:194] Registered new tserver with Master: a714cec1ea4a4cc5a59bd8101097ecb1 (127.16.82.65:33121)
I20260812 06:18:24.099292 16713 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008864996s
I20260812 06:18:24.099678 17051 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57468
I20260812 06:18:24.106731 17051 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57480:
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:24.116462 17197 tablet_service.cc:1511] Processing CreateTablet for tablet 5479b245581b4cbdac128e9e3ddf9593 (DEFAULT_TABLE table=heavy-update-compaction-test [id=47f704ecb74040f8b912846155bf56fd]), partition=
I20260812 06:18:24.116808 17197 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5479b245581b4cbdac128e9e3ddf9593. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:24.119005 17266 tablet_bootstrap.cc:492] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Bootstrap starting.
I20260812 06:18:24.119935 17266 tablet_bootstrap.cc:654] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:24.121187 17266 tablet_bootstrap.cc:492] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: No bootstrap required, opened a new log
I20260812 06:18:24.121294 17266 ts_tablet_manager.cc:1403] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:24.121959 17266 raft_consensus.cc:359] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a714cec1ea4a4cc5a59bd8101097ecb1" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 33121 } }
I20260812 06:18:24.122062 17266 raft_consensus.cc:385] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:24.122092 17266 raft_consensus.cc:740] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a714cec1ea4a4cc5a59bd8101097ecb1, State: Initialized, Role: FOLLOWER
I20260812 06:18:24.122234 17266 consensus_queue.cc:260] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [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: "a714cec1ea4a4cc5a59bd8101097ecb1" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 33121 } }
I20260812 06:18:24.122326 17266 raft_consensus.cc:399] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:24.122351 17266 raft_consensus.cc:493] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:24.122388 17266 raft_consensus.cc:3060] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:24.123251 17266 raft_consensus.cc:515] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a714cec1ea4a4cc5a59bd8101097ecb1" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 33121 } }
I20260812 06:18:24.123375 17266 leader_election.cc:304] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [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: a714cec1ea4a4cc5a59bd8101097ecb1; no voters: 
I20260812 06:18:24.123538 17266 leader_election.cc:290] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:24.123703 17268 raft_consensus.cc:2804] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:24.123888 17266 ts_tablet_manager.cc:1434] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Time spent starting tablet: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:18:24.123909 17246 heartbeater.cc:499] Master 127.16.82.126:44289 was elected leader, sending a full tablet report...
I20260812 06:18:24.123946 17268 raft_consensus.cc:697] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 1 LEADER]: Becoming Leader. State: Replica: a714cec1ea4a4cc5a59bd8101097ecb1, State: Running, Role: LEADER
I20260812 06:18:24.124074 17268 consensus_queue.cc:237] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [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: "a714cec1ea4a4cc5a59bd8101097ecb1" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 33121 } }
I20260812 06:18:24.125393 17051 catalog_manager.cc:5719] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 reported cstate change: term changed from 0 to 1, leader changed from <none> to a714cec1ea4a4cc5a59bd8101097ecb1 (127.16.82.65). New cstate: current_term: 1 leader_uuid: "a714cec1ea4a4cc5a59bd8101097ecb1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a714cec1ea4a4cc5a59bd8101097ecb1" member_type: VOTER last_known_addr { host: "127.16.82.65" port: 33121 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:24.191491 16713 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.017s	sys 0.008s
I20260812 06:18:24.341296 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593): perf score=15.086190
I20260812 06:18:24.526206 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.185s	user 0.124s	sys 0.051s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1029,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45491,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:18:24.527040 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling LogGCOp(5479b245581b4cbdac128e9e3ddf9593): free 20743880 bytes of WAL
I20260812 06:18:24.527292 17162 log_reader.cc:385] T 5479b245581b4cbdac128e9e3ddf9593: removed 2 log segments from log reader
I20260812 06:18:24.527343 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000001 (ops 1-6)
I20260812 06:18:24.527398 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000002 (ops 7-11)
I20260812 06:18:24.531982 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: LogGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:24.532358 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling UndoDeltaBlockGCOp(5479b245581b4cbdac128e9e3ddf9593): 12719216 bytes on disk
I20260812 06:18:24.532856 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: UndoDeltaBlockGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.533300 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:24.547240 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.547783 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:24.726711 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.179s	user 0.122s	sys 0.057s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262035,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":464,"lbm_read_time_us":13160,"lbm_reads_lt_1ms":454,"lbm_write_time_us":31702,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":381,"threads_started":5,"update_count":1950}
I20260812 06:18:24.727372 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:24.766881 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.039s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17421,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.767599 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:24.783576 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.784106 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:24.933425 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.149s	user 0.100s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":10249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29383,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":68736,"update_count":2000}
I20260812 06:18:24.934083 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:24.986088 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.052s	user 0.009s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17712,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.986729 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:24.999735 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.000423 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:25.154714 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.154s	user 0.125s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":715,"lbm_read_time_us":11739,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27625,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:25.155284 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:25.211962 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.056s	user 0.032s	sys 0.006s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.212572 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:25.224617 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.225142 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:25.374945 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.150s	user 0.105s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1475,"lbm_read_time_us":11294,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27867,"lbm_writes_lt_1ms":443,"mutex_wait_us":365,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:25.375504 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:25.430696 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.055s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17052,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.431384 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:25.443874 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.444372 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:25.609061 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.164s	user 0.093s	sys 0.070s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":741,"lbm_read_time_us":13162,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25659,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:18:25.609696 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:25.658603 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.049s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17601,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.659265 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:25.672020 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.672803 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:25.824525 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.151s	user 0.117s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":10216,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28917,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:25.825361 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:25.880856 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.055s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19970,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.881494 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:25.893215 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.894044 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:26.044165 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.150s	user 0.122s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1242,"lbm_read_time_us":10240,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30927,"lbm_writes_lt_1ms":443,"mutex_wait_us":361,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":144256,"update_count":2000}
I20260812 06:18:26.044971 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:26.101487 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.056s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18028,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.102131 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:26.114785 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.115412 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:26.164484 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.049s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1332,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1836,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:26.165335 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling LogGCOp(5479b245581b4cbdac128e9e3ddf9593): free 124710298 bytes of WAL
I20260812 06:18:26.165637 17162 log_reader.cc:385] T 5479b245581b4cbdac128e9e3ddf9593: removed 12 log segments from log reader
I20260812 06:18:26.165700 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000003 (ops 12-16)
I20260812 06:18:26.165742 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000004 (ops 17-21)
I20260812 06:18:26.165772 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000005 (ops 22-26)
I20260812 06:18:26.165805 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000006 (ops 27-31)
I20260812 06:18:26.165838 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000007 (ops 32-36)
I20260812 06:18:26.165869 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000008 (ops 37-41)
I20260812 06:18:26.165899 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000009 (ops 42-46)
I20260812 06:18:26.165927 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000010 (ops 47-51)
I20260812 06:18:26.165957 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000011 (ops 52-56)
I20260812 06:18:26.165992 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000012 (ops 57-61)
I20260812 06:18:26.166023 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000013 (ops 62-66)
I20260812 06:18:26.166050 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000014 (ops 67-71)
I20260812 06:18:26.200809 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: LogGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:18:26.201424 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=3.181125
I20260812 06:18:26.227715 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.026s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":5635,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:18:26.228363 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling UndoDeltaBlockGCOp(5479b245581b4cbdac128e9e3ddf9593): 483 bytes on disk
I20260812 06:18:26.228938 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: UndoDeltaBlockGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.229449 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:26.246344 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.017s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":6192,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:26.247044 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:26.482244 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.235s	user 0.129s	sys 0.104s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2267,"lbm_read_time_us":16214,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38402,"lbm_writes_lt_1ms":643,"mutex_wait_us":1620,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:18:26.483285 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=14.095187
I20260812 06:18:26.574364 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.091s	user 0.030s	sys 0.022s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":62039,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.575047 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:26.589327 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.589923 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:26.799587 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.209s	user 0.168s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4167,"dirs.run_cpu_time_us":663,"dirs.run_wall_time_us":3876,"lbm_read_time_us":14510,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35401,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:26.800369 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=14.095187
I20260812 06:18:26.876955 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.076s	user 0.047s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28092,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.877638 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:26.891842 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.892409 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:27.089341 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.197s	user 0.129s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":368,"lbm_read_time_us":15700,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33657,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:27.090152 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=11.118625
I20260812 06:18:27.130152 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.040s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17182,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:27.130766 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:27.149437 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7001,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.150154 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:27.321419 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.171s	user 0.076s	sys 0.095s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":11688,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29239,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:18:27.322364 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:27.366402 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.044s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17678,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.367129 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:27.385694 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.386528 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:27.606894 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.220s	user 0.175s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":311,"lbm_read_time_us":10835,"lbm_reads_lt_1ms":472,"lbm_write_time_us":44483,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":121,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29824,"update_count":2000}
I20260812 06:18:27.608100 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=14.095187
I20260812 06:18:27.680002 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.067s	user 0.055s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29655,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.680907 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:27.698396 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.699295 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:27.890722 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.191s	user 0.131s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":14329,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32341,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:18:27.891695 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:27.934007 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.042s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19354,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.934624 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:27.972084 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.037s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1266,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2247,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:27.972915 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling LogGCOp(5479b245581b4cbdac128e9e3ddf9593): free 112239321 bytes of WAL
I20260812 06:18:27.973187 17162 log_reader.cc:385] T 5479b245581b4cbdac128e9e3ddf9593: removed 11 log segments from log reader
I20260812 06:18:27.973256 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000015 (ops 72-76)
I20260812 06:18:27.973323 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000016 (ops 77-80)
I20260812 06:18:27.973384 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000017 (ops 81-85)
I20260812 06:18:27.973443 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000018 (ops 86-90)
I20260812 06:18:27.973489 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000019 (ops 91-95)
I20260812 06:18:27.973555 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000020 (ops 96-100)
I20260812 06:18:27.973600 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000021 (ops 101-105)
I20260812 06:18:27.973644 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000022 (ops 106-110)
I20260812 06:18:27.973690 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000023 (ops 111-115)
I20260812 06:18:27.973734 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000024 (ops 116-120)
I20260812 06:18:27.973778 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000025 (ops 121-125)
I20260812 06:18:28.000115 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: LogGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:28.000607 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:28.019306 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.019s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.019902 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling LogGCOp(5479b245581b4cbdac128e9e3ddf9593): free 8767131 bytes of WAL
I20260812 06:18:28.020195 17162 log_reader.cc:385] T 5479b245581b4cbdac128e9e3ddf9593: removed 1 log segments from log reader
I20260812 06:18:28.020262 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000026 (ops 126-130)
I20260812 06:18:28.022603 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: LogGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:28.023147 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:28.036111 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.036974 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:28.255344 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.218s	user 0.125s	sys 0.084s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2235,"lbm_read_time_us":15695,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35503,"lbm_writes_lt_1ms":543,"mutex_wait_us":1442,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":97,"threads_started":1,"update_count":2500}
I20260812 06:18:28.256196 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=14.095187
I20260812 06:18:28.310129 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.054s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23531,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.310722 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling UndoDeltaBlockGCOp(5479b245581b4cbdac128e9e3ddf9593): 461 bytes on disk
I20260812 06:18:28.311210 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: UndoDeltaBlockGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.311774 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:28.482225 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.170s	user 0.103s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":470,"lbm_read_time_us":11464,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25906,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2000}
I20260812 06:18:28.483186 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=14.095187
I20260812 06:18:28.539994 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24630,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.540623 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:28.553486 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.554338 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:28.774444 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.220s	user 0.143s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":698,"lbm_read_time_us":13454,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34796,"lbm_writes_lt_1ms":543,"mutex_wait_us":328,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:18:28.775203 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=14.095187
I20260812 06:18:28.837692 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.062s	user 0.034s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25125,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.838302 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:28.851576 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.852149 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:29.017256 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.165s	user 0.108s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2622,"lbm_read_time_us":12692,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31695,"lbm_writes_lt_1ms":543,"mutex_wait_us":741,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:29.018049 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:29.069671 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.051s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18192,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.070279 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:29.083287 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.084123 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:29.237629 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.153s	user 0.134s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":9617,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29965,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":2000}
I20260812 06:18:29.238605 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:29.287806 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.049s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17970,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.288405 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:29.307287 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.019s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.308074 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:29.459007 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.151s	user 0.135s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4089,"lbm_read_time_us":12366,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28465,"lbm_writes_lt_1ms":443,"mutex_wait_us":3283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:29.460543 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:29.520341 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.060s	user 0.029s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17556,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.521207 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:29.543223 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.022s	user 0.018s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.543979 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:29.712085 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.168s	user 0.099s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":673,"lbm_read_time_us":14659,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26248,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:29.713053 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:29.757390 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.044s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19191,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.758056 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:29.770854 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4747,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.771764 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:29.803246 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushMRSOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1569,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1753,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:29.803944 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling LogGCOp(5479b245581b4cbdac128e9e3ddf9593): free 124710562 bytes of WAL
I20260812 06:18:29.804185 17162 log_reader.cc:385] T 5479b245581b4cbdac128e9e3ddf9593: removed 12 log segments from log reader
I20260812 06:18:29.804235 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000027 (ops 131-135)
I20260812 06:18:29.804270 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000028 (ops 136-140)
I20260812 06:18:29.804333 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000029 (ops 141-145)
I20260812 06:18:29.804395 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000030 (ops 146-150)
I20260812 06:18:29.804435 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000031 (ops 151-155)
I20260812 06:18:29.804474 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000032 (ops 156-160)
I20260812 06:18:29.804513 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000033 (ops 161-165)
I20260812 06:18:29.804553 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000034 (ops 166-170)
I20260812 06:18:29.804590 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000035 (ops 171-175)
I20260812 06:18:29.804625 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000036 (ops 176-180)
I20260812 06:18:29.804663 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000037 (ops 181-185)
I20260812 06:18:29.804705 17162 log.cc:1079] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: Deleting log segment in path: /tmp/dist-test-taskTKldB4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497702803-16713-0/minicluster-data/ts-0-root/wals/5479b245581b4cbdac128e9e3ddf9593/wal-000000038 (ops 186-190)
I20260812 06:18:29.831905 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: LogGCOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:29.832432 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:29.865418 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.033s	user 0.013s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.866003 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=2.188937
I20260812 06:18:29.878270 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.878856 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593): perf score=1.000000
I20260812 06:18:30.059144 16713 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.868s	user 2.169s	sys 0.239s
I20260812 06:18:30.101204 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: MajorDeltaCompactionOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.222s	user 0.143s	sys 0.077s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":19077,"lbm_reads_lt_1ms":670,"lbm_write_time_us":37460,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":3000}
I20260812 06:18:30.101924 17248 maintenance_manager.cc:419] P a714cec1ea4a4cc5a59bd8101097ecb1: Scheduling FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593): perf score=10.126437
I20260812 06:18:30.143419 16713 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.003s	sys 0.000s
I20260812 06:18:30.144109 16713 tablet_server.cc:179] TabletServer@127.16.82.65:0 shutting down...
I20260812 06:18:30.152359 17162 maintenance_manager.cc:643] P a714cec1ea4a4cc5a59bd8101097ecb1: FlushDeltaMemStoresOp(5479b245581b4cbdac128e9e3ddf9593) complete. Timing: real 0.050s	user 0.033s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22294,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.152908 16713 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:30.153163 16713 tablet_replica.cc:333] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1: stopping tablet replica
I20260812 06:18:30.153296 16713 raft_consensus.cc:2243] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:30.153532 16713 raft_consensus.cc:2272] T 5479b245581b4cbdac128e9e3ddf9593 P a714cec1ea4a4cc5a59bd8101097ecb1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:30.168744 16713 tablet_server.cc:196] TabletServer@127.16.82.65:0 shutdown complete.
I20260812 06:18:30.178541 16713 master.cc:562] Master@127.16.82.126:44289 shutting down...
I20260812 06:18:30.183207 16713 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:30.183431 16713 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:30.183535 16713 tablet_replica.cc:333] T 00000000000000000000000000000000 P bcf602fbef884d15aafbd85b6ab1959a: stopping tablet replica
I20260812 06:18:30.196105 16713 master.cc:584] Master@127.16.82.126:44289 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6302 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12574 ms total)

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