[==========] 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:25.816684  4987 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.222.254:41469
I20260812 06:18:25.817646  4987 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:25.818193  4987 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:25.825177  4993 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:25.825248  4987 server_base.cc:1061] running on GCE node
W20260812 06:18:25.825188  4994 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:25.825654  4996 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:25.826192  4987 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:25.826285  4987 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:25.826333  4987 hybrid_clock.cc:648] HybridClock initialized: now 1786515505826311 us; error 0 us; skew 500 ppm
I20260812 06:18:25.828229  4987 webserver.cc:533] Webserver started at http://127.4.222.254:40769/ using document root <none> and password file <none>
I20260812 06:18:25.828774  4987 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:25.828845  4987 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:25.829104  4987 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:25.830843  4987 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/master-0-root/instance:
uuid: "2eedddc2fced4cecb01aad7e65247a40"
format_stamp: "Formatted at 2026-08-12 06:18:25 on dist-test-slave-zpfg"
I20260812 06:18:25.834470  4987 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:25.836686  5001 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:25.838182  4987 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:25.838394  4987 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/master-0-root
uuid: "2eedddc2fced4cecb01aad7e65247a40"
format_stamp: "Formatted at 2026-08-12 06:18:25 on dist-test-slave-zpfg"
I20260812 06:18:25.838526  4987 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-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:25.858575  4987 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:25.859442  4987 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:25.859648  4987 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:25.868672  5057 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.222.254:41469 every 8 connection(s)
I20260812 06:18:25.868669  4987 rpc_server.cc:307] RPC server started. Bound to: 127.4.222.254:41469
I20260812 06:18:25.871574  5058 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:25.877748  5058 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40: Bootstrap starting.
I20260812 06:18:25.880558  5058 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:25.881666  5058 log.cc:826] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:25.883786  5058 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40: No bootstrap required, opened a new log
I20260812 06:18:25.887082  5058 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eedddc2fced4cecb01aad7e65247a40" member_type: VOTER }
I20260812 06:18:25.887282  5058 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:25.887401  5058 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2eedddc2fced4cecb01aad7e65247a40, State: Initialized, Role: FOLLOWER
I20260812 06:18:25.888116  5058 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [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: "2eedddc2fced4cecb01aad7e65247a40" member_type: VOTER }
I20260812 06:18:25.888366  5058 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:25.888502  5058 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:25.888680  5058 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:25.889631  5058 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eedddc2fced4cecb01aad7e65247a40" member_type: VOTER }
I20260812 06:18:25.890164  5058 leader_election.cc:304] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [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: 2eedddc2fced4cecb01aad7e65247a40; no voters: 
I20260812 06:18:25.890584  5058 leader_election.cc:290] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:25.890823  5061 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:25.891072  5061 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 1 LEADER]: Becoming Leader. State: Replica: 2eedddc2fced4cecb01aad7e65247a40, State: Running, Role: LEADER
I20260812 06:18:25.891501  5061 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [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: "2eedddc2fced4cecb01aad7e65247a40" member_type: VOTER }
I20260812 06:18:25.891729  5058 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:25.893397  5062 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2eedddc2fced4cecb01aad7e65247a40" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eedddc2fced4cecb01aad7e65247a40" member_type: VOTER } }
I20260812 06:18:25.893450  5063 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2eedddc2fced4cecb01aad7e65247a40. Latest consensus state: current_term: 1 leader_uuid: "2eedddc2fced4cecb01aad7e65247a40" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2eedddc2fced4cecb01aad7e65247a40" member_type: VOTER } }
I20260812 06:18:25.893532  5062 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:25.893553  5063 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:25.893968  5070 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:25.896781  5070 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:25.897156  4987 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:25.901957  5070 catalog_manager.cc:1383] Generated new cluster ID: 5c05d33c62434d8e9d5309c24dab3d2f
I20260812 06:18:25.902051  5070 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:25.923691  5070 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:25.925009  5070 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:25.932312  5070 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40: Generated new TSK 0
I20260812 06:18:25.933175  5070 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:25.962276  4987 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:25.965251  5080 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:25.965405  5081 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:25.965430  5083 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:25.966229  4987 server_base.cc:1061] running on GCE node
I20260812 06:18:25.966457  4987 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:25.966516  4987 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:25.966542  4987 hybrid_clock.cc:648] HybridClock initialized: now 1786515505966541 us; error 0 us; skew 500 ppm
I20260812 06:18:25.967592  4987 webserver.cc:533] Webserver started at http://127.4.222.193:32943/ using document root <none> and password file <none>
I20260812 06:18:25.967787  4987 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:25.967854  4987 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:25.967940  4987 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:25.968426  4987 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/instance:
uuid: "ff88a2680ff5463798c98bb0ed29da3d"
format_stamp: "Formatted at 2026-08-12 06:18:25 on dist-test-slave-zpfg"
I20260812 06:18:25.970523  4987 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:25.971740  5088 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:25.972059  4987 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:25.972124  4987 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root
uuid: "ff88a2680ff5463798c98bb0ed29da3d"
format_stamp: "Formatted at 2026-08-12 06:18:25 on dist-test-slave-zpfg"
I20260812 06:18:25.972213  4987 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-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:25.983166  4987 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:25.983639  4987 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:25.984158  4987 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:25.985060  4987 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:25.985116  4987 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:25.985188  4987 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:25.985225  4987 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:25.992283  4987 rpc_server.cc:307] RPC server started. Bound to: 127.4.222.193:37111
I20260812 06:18:25.992318  5154 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.222.193:37111 every 8 connection(s)
I20260812 06:18:26.010404  5155 heartbeater.cc:344] Connected to a master server at 127.4.222.254:41469
I20260812 06:18:26.010704  5155 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:26.011209  5155 heartbeater.cc:507] Master 127.4.222.254:41469 requested a full tablet report, sending...
I20260812 06:18:26.012713  5020 ts_manager.cc:194] Registered new tserver with Master: ff88a2680ff5463798c98bb0ed29da3d (127.4.222.193:37111)
I20260812 06:18:26.013010  4987 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.02004993s
I20260812 06:18:26.014081  5020 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52878
I20260812 06:18:26.023161  5020 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52890:
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:26.037309  5117 tablet_service.cc:1511] Processing CreateTablet for tablet 328149c0ef764be9b7b6cd8f9f6401bf (DEFAULT_TABLE table=heavy-update-compaction-test [id=9649c04e515045e6a3ddfea0a9fba89b]), partition=
I20260812 06:18:26.037825  5117 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 328149c0ef764be9b7b6cd8f9f6401bf. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:26.040205  5167 tablet_bootstrap.cc:492] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Bootstrap starting.
I20260812 06:18:26.041179  5167 tablet_bootstrap.cc:654] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:26.042555  5167 tablet_bootstrap.cc:492] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: No bootstrap required, opened a new log
I20260812 06:18:26.042673  5167 ts_tablet_manager.cc:1403] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:26.043191  5167 raft_consensus.cc:359] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ff88a2680ff5463798c98bb0ed29da3d" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 37111 } }
I20260812 06:18:26.043322  5167 raft_consensus.cc:385] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:26.043365  5167 raft_consensus.cc:740] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ff88a2680ff5463798c98bb0ed29da3d, State: Initialized, Role: FOLLOWER
I20260812 06:18:26.043499  5167 consensus_queue.cc:260] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [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: "ff88a2680ff5463798c98bb0ed29da3d" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 37111 } }
I20260812 06:18:26.043587  5167 raft_consensus.cc:399] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:26.043623  5167 raft_consensus.cc:493] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:26.043682  5167 raft_consensus.cc:3060] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:26.044678  5167 raft_consensus.cc:515] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ff88a2680ff5463798c98bb0ed29da3d" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 37111 } }
I20260812 06:18:26.044832  5167 leader_election.cc:304] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [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: ff88a2680ff5463798c98bb0ed29da3d; no voters: 
I20260812 06:18:26.045054  5167 leader_election.cc:290] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:26.045177  5169 raft_consensus.cc:2804] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:26.045449  5167 ts_tablet_manager.cc:1434] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:26.045755  5155 heartbeater.cc:499] Master 127.4.222.254:41469 was elected leader, sending a full tablet report...
I20260812 06:18:26.045595  5169 raft_consensus.cc:697] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 1 LEADER]: Becoming Leader. State: Replica: ff88a2680ff5463798c98bb0ed29da3d, State: Running, Role: LEADER
I20260812 06:18:26.046236  5169 consensus_queue.cc:237] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [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: "ff88a2680ff5463798c98bb0ed29da3d" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 37111 } }
I20260812 06:18:26.048905  5020 catalog_manager.cc:5719] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d reported cstate change: term changed from 0 to 1, leader changed from <none> to ff88a2680ff5463798c98bb0ed29da3d (127.4.222.193). New cstate: current_term: 1 leader_uuid: "ff88a2680ff5463798c98bb0ed29da3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ff88a2680ff5463798c98bb0ed29da3d" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 37111 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:26.117904  4987 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.023s	sys 0.003s
I20260812 06:18:26.243609  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=15.086190
I20260812 06:18:26.415187  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.171s	user 0.125s	sys 0.040s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":310,"delete_count":0,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":998,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41097,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":222,"threads_started":1,"update_count":1450}
I20260812 06:18:26.416543  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf): free 20743880 bytes of WAL
I20260812 06:18:26.416883  5094 log_reader.cc:385] T 328149c0ef764be9b7b6cd8f9f6401bf: removed 2 log segments from log reader
I20260812 06:18:26.416967  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000001 (ops 1-6)
I20260812 06:18:26.417044  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000002 (ops 7-11)
I20260812 06:18:26.421300  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:26.421684  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf): 12719216 bytes on disk
I20260812 06:18:26.422290  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.422778  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:26.439196  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.439699  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:26.568758  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.129s	user 0.095s	sys 0.033s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":911,"lbm_read_time_us":9337,"lbm_reads_lt_1ms":454,"lbm_write_time_us":23726,"lbm_writes_lt_1ms":433,"mutex_wait_us":78,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":312,"threads_started":5,"update_count":1950}
I20260812 06:18:26.569245  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:26.612123  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.043s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16162,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.612551  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:26.623057  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.623525  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:26.759632  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.136s	user 0.092s	sys 0.040s 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":357,"lbm_read_time_us":8520,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27133,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:26.760192  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:26.799245  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.039s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14867,"lbm_writes_lt_1ms":303,"mutex_wait_us":4,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:26.799837  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:26.906219  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.106s	user 0.077s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1108,"lbm_read_time_us":6216,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17892,"lbm_writes_lt_1ms":343,"mutex_wait_us":21,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":1500}
I20260812 06:18:26.906870  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:26.944048  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.037s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14165,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.944515  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:26.956017  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.956750  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:27.090001  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.133s	user 0.119s	sys 0.013s 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":698,"lbm_read_time_us":9250,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24949,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:27.090685  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:27.132336  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.041s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15470,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.132875  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:27.144081  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.144709  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:27.275259  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.130s	user 0.086s	sys 0.039s 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":260,"lbm_read_time_us":9581,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24990,"lbm_writes_lt_1ms":443,"mutex_wait_us":89,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:27.276238  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:27.314230  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.038s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15700,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.314889  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:27.416038  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.101s	user 0.071s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":344,"lbm_read_time_us":5715,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19993,"lbm_writes_lt_1ms":343,"mutex_wait_us":2,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:27.416833  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:27.457352  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.040s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15503,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:18:27.457810  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:27.468901  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.469564  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:27.610961  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.141s	user 0.090s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1535,"lbm_read_time_us":7992,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24242,"lbm_writes_lt_1ms":443,"mutex_wait_us":990,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:27.611577  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:27.654237  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.042s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18176,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:18:27.654835  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:27.665521  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.666326  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:27.699337  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.033s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1787,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1899,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:27.700201  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf): free 112239312 bytes of WAL
I20260812 06:18:27.700475  5094 log_reader.cc:385] T 328149c0ef764be9b7b6cd8f9f6401bf: removed 11 log segments from log reader
I20260812 06:18:27.700521  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000003 (ops 12-16)
I20260812 06:18:27.700552  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000004 (ops 17-20)
I20260812 06:18:27.700639  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000005 (ops 21-25)
I20260812 06:18:27.700706  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000006 (ops 26-30)
I20260812 06:18:27.700744  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000007 (ops 31-35)
I20260812 06:18:27.700785  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000008 (ops 36-40)
I20260812 06:18:27.700824  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000009 (ops 41-45)
I20260812 06:18:27.700870  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000010 (ops 46-50)
I20260812 06:18:27.700907  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000011 (ops 51-55)
I20260812 06:18:27.700946  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000012 (ops 56-60)
I20260812 06:18:27.700987  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000013 (ops 61-65)
I20260812 06:18:27.723443  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:27.723906  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf): 462 bytes on disk
I20260812 06:18:27.724457  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.724910  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=3.181125
I20260812 06:18:27.738116  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4546,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:27.738636  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf): free 12017932 bytes of WAL
I20260812 06:18:27.738862  5094 log_reader.cc:385] T 328149c0ef764be9b7b6cd8f9f6401bf: removed 1 log segments from log reader
I20260812 06:18:27.738940  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000014 (ops 66-70)
I20260812 06:18:27.741580  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:27.741974  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:27.753863  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4133,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.754487  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:27.955480  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.201s	user 0.158s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3853,"lbm_read_time_us":12961,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41732,"lbm_writes_lt_1ms":643,"mutex_wait_us":1722,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:27.956317  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:28.009181  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.053s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19550,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.009806  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:28.024139  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.024746  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:28.180855  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.156s	user 0.104s	sys 0.042s 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":534,"lbm_read_time_us":10592,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33491,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:28.181841  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=11.118625
I20260812 06:18:28.213200  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13680,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.214078  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:28.233566  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6250,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.234265  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:28.380172  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.146s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":507,"lbm_read_time_us":10239,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28053,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:18:28.380966  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:28.420490  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.039s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16689,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.421010  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:28.431576  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.432056  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:28.562062  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.130s	user 0.100s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":9182,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24951,"lbm_writes_lt_1ms":443,"mutex_wait_us":306,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:28.562722  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:28.619849  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.057s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14495,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.620465  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:28.637338  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.637988  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:28.778786  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.141s	user 0.106s	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":594,"lbm_read_time_us":11588,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22031,"lbm_writes_lt_1ms":443,"mutex_wait_us":272,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:28.779429  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:28.830394  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.051s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16080,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.830883  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:28.841694  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.842509  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:28.968199  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.125s	user 0.092s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1097,"lbm_read_time_us":9570,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23006,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:28.968881  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:29.020783  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.052s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19267,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.021585  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:29.037622  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.038168  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:29.172494  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.134s	user 0.096s	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":590,"lbm_read_time_us":8929,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26456,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:29.173322  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:29.227747  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.054s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16595,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.228350  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:29.239543  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.240037  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:29.284147  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.044s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1262,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1488,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:29.285058  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf): free 120553382 bytes of WAL
I20260812 06:18:29.285291  5094 log_reader.cc:385] T 328149c0ef764be9b7b6cd8f9f6401bf: removed 12 log segments from log reader
I20260812 06:18:29.285339  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000015 (ops 71-75)
I20260812 06:18:29.285370  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000016 (ops 76-80)
I20260812 06:18:29.285437  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000017 (ops 81-84)
I20260812 06:18:29.285499  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000018 (ops 85-89)
I20260812 06:18:29.285540  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000019 (ops 90-94)
I20260812 06:18:29.285596  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000020 (ops 95-99)
I20260812 06:18:29.285633  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000021 (ops 100-104)
I20260812 06:18:29.285665  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000022 (ops 105-109)
I20260812 06:18:29.285704  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000023 (ops 110-114)
I20260812 06:18:29.285728  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000024 (ops 115-119)
I20260812 06:18:29.285769  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000025 (ops 120-124)
I20260812 06:18:29.285809  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000026 (ops 125-128)
I20260812 06:18:29.311146  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:29.311805  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:29.328840  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.017s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.329344  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:29.340055  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.340622  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:29.540829  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.200s	user 0.123s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2804,"lbm_read_time_us":14828,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32209,"lbm_writes_lt_1ms":643,"mutex_wait_us":1926,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:29.541777  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf): 482 bytes on disk
I20260812 06:18:29.542364  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.543228  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:29.595494  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.052s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.595994  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:29.744855  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.149s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":478,"lbm_read_time_us":9049,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23011,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:29.745609  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:29.796552  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.051s	user 0.037s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18653,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.797087  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:29.808707  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.809157  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:29.998395  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.189s	user 0.115s	sys 0.065s 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":1152,"lbm_read_time_us":12297,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28566,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:29.999064  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:30.053666  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.054s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23809,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.054217  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:30.075667  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.076251  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:30.246587  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.170s	user 0.128s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1520,"lbm_read_time_us":10241,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33185,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:18:30.247169  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:30.303602  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.056s	user 0.019s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25541,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.304229  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:30.318099  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.318742  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:30.476814  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.158s	user 0.125s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":10153,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31755,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:30.477530  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:30.532680  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.055s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26113,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.533361  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:30.544979  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.545492  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:30.705847  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.160s	user 0.118s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":656,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32571,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:30.706561  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=14.095187
I20260812 06:18:30.757184  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.050s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21978,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.757758  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:30.770298  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.770963  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:30.805506  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushMRSOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1602,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1886,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:30.806389  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf): free 133024644 bytes of WAL
I20260812 06:18:30.806672  5094 log_reader.cc:385] T 328149c0ef764be9b7b6cd8f9f6401bf: removed 13 log segments from log reader
I20260812 06:18:30.806768  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000027 (ops 129-133)
I20260812 06:18:30.806859  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000028 (ops 134-138)
I20260812 06:18:30.806948  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000029 (ops 139-143)
I20260812 06:18:30.807024  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000030 (ops 144-148)
I20260812 06:18:30.807097  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000031 (ops 149-152)
I20260812 06:18:30.807188  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000032 (ops 153-157)
I20260812 06:18:30.807263  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000033 (ops 158-162)
I20260812 06:18:30.807339  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000034 (ops 163-167)
I20260812 06:18:30.807410  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000035 (ops 168-172)
I20260812 06:18:30.807487  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000036 (ops 173-177)
I20260812 06:18:30.807559  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000037 (ops 178-182)
I20260812 06:18:30.807632  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000038 (ops 183-187)
I20260812 06:18:30.807719  5094 log.cc:1079] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/328149c0ef764be9b7b6cd8f9f6401bf/wal-000000039 (ops 188-192)
I20260812 06:18:30.837754  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: LogGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:30.838282  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf): 482 bytes on disk
I20260812 06:18:30.838948  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: UndoDeltaBlockGCOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.839571  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=3.181125
I20260812 06:18:30.854281  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":5814,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:18:30.854846  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=2.188937
I20260812 06:18:30.864636  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3307,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:30.865252  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:30.981627  4987 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.864s	user 1.836s	sys 0.109s
I20260812 06:18:31.040472  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.175s	user 0.141s	sys 0.032s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979728,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":13344,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35716,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:18:31.040956  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=10.126437
I20260812 06:18:31.075177  4987 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.006s	sys 0.000s
I20260812 06:18:31.075980  4987 tablet_server.cc:179] TabletServer@127.4.222.193:0 shutting down...
I20260812 06:18:31.080112  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: FlushDeltaMemStoresOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.039s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16561,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.084929  5156 maintenance_manager.cc:419] P ff88a2680ff5463798c98bb0ed29da3d: Scheduling MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf): perf score=1.000000
I20260812 06:18:31.184746  5094 maintenance_manager.cc:643] P ff88a2680ff5463798c98bb0ed29da3d: MajorDeltaCompactionOp(328149c0ef764be9b7b6cd8f9f6401bf) complete. Timing: real 0.100s	user 0.074s	sys 0.023s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":473,"lbm_read_time_us":7910,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18517,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.185500  4987 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:31.185963  4987 tablet_replica.cc:333] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d: stopping tablet replica
I20260812 06:18:31.186201  4987 raft_consensus.cc:2243] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:31.186484  4987 raft_consensus.cc:2272] T 328149c0ef764be9b7b6cd8f9f6401bf P ff88a2680ff5463798c98bb0ed29da3d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:31.192466  4987 tablet_server.cc:196] TabletServer@127.4.222.193:0 shutdown complete.
I20260812 06:18:31.218014  4987 master.cc:562] Master@127.4.222.254:41469 shutting down...
I20260812 06:18:31.222316  4987 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:31.222564  4987 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:31.222627  4987 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2eedddc2fced4cecb01aad7e65247a40: stopping tablet replica
I20260812 06:18:31.235527  4987 master.cc:584] Master@127.4.222.254:41469 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5513 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:31.346421  4987 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.222.254:33021
I20260812 06:18:31.346827  4987 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:31.349546  5186 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:31.349609  5189 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:31.349594  4987 server_base.cc:1061] running on GCE node
W20260812 06:18:31.349634  5187 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:31.350030  4987 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:31.350100  4987 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:31.350123  4987 hybrid_clock.cc:648] HybridClock initialized: now 1786515511350123 us; error 0 us; skew 500 ppm
I20260812 06:18:31.351176  4987 webserver.cc:533] Webserver started at http://127.4.222.254:33513/ using document root <none> and password file <none>
I20260812 06:18:31.351367  4987 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:31.351442  4987 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:31.351524  4987 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:31.351966  4987 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/master-0-root/instance:
uuid: "294bb9e5669841389504fed701b5169b"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-zpfg"
I20260812 06:18:31.353649  4987 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:31.354900  5195 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:31.355216  4987 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:31.355311  4987 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/master-0-root
uuid: "294bb9e5669841389504fed701b5169b"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-zpfg"
I20260812 06:18:31.355404  4987 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-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:31.366307  4987 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:31.366959  4987 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:31.371479  4987 rpc_server.cc:307] RPC server started. Bound to: 127.4.222.254:33021
I20260812 06:18:31.375044  5247 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.222.254:33021 every 8 connection(s)
I20260812 06:18:31.375445  5248 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:31.377264  5248 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b: Bootstrap starting.
I20260812 06:18:31.378007  5248 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:31.379086  5248 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b: No bootstrap required, opened a new log
I20260812 06:18:31.379601  5248 raft_consensus.cc:359] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "294bb9e5669841389504fed701b5169b" member_type: VOTER }
I20260812 06:18:31.379703  5248 raft_consensus.cc:385] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:31.379729  5248 raft_consensus.cc:740] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 294bb9e5669841389504fed701b5169b, State: Initialized, Role: FOLLOWER
I20260812 06:18:31.379878  5248 consensus_queue.cc:260] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [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: "294bb9e5669841389504fed701b5169b" member_type: VOTER }
I20260812 06:18:31.379974  5248 raft_consensus.cc:399] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:31.380000  5248 raft_consensus.cc:493] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:31.380031  5248 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:31.380767  5248 raft_consensus.cc:515] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "294bb9e5669841389504fed701b5169b" member_type: VOTER }
I20260812 06:18:31.380887  5248 leader_election.cc:304] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [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: 294bb9e5669841389504fed701b5169b; no voters: 
I20260812 06:18:31.381038  5248 leader_election.cc:290] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:31.381191  5251 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:31.381455  5251 raft_consensus.cc:697] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 1 LEADER]: Becoming Leader. State: Replica: 294bb9e5669841389504fed701b5169b, State: Running, Role: LEADER
I20260812 06:18:31.381615  5248 sys_catalog.cc:565] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:31.381610  5251 consensus_queue.cc:237] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [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: "294bb9e5669841389504fed701b5169b" member_type: VOTER }
I20260812 06:18:31.382203  5252 sys_catalog.cc:455] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "294bb9e5669841389504fed701b5169b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "294bb9e5669841389504fed701b5169b" member_type: VOTER } }
I20260812 06:18:31.382262  5253 sys_catalog.cc:455] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 294bb9e5669841389504fed701b5169b. Latest consensus state: current_term: 1 leader_uuid: "294bb9e5669841389504fed701b5169b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "294bb9e5669841389504fed701b5169b" member_type: VOTER } }
I20260812 06:18:31.382375  5252 sys_catalog.cc:458] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:31.382472  5253 sys_catalog.cc:458] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:31.383024  5257 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:31.383859  5257 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:31.384166  4987 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:31.385759  5257 catalog_manager.cc:1383] Generated new cluster ID: fbf04e558a6d45379085827034e9b4c6
I20260812 06:18:31.385812  5257 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:31.390410  5257 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:31.390972  5257 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:31.399636  5257 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b: Generated new TSK 0
I20260812 06:18:31.399892  5257 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:31.416766  4987 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:31.419139  5272 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:31.419102  5269 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:31.419268  4987 server_base.cc:1061] running on GCE node
W20260812 06:18:31.419268  5270 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:31.419687  4987 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:31.419734  4987 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:31.419755  4987 hybrid_clock.cc:648] HybridClock initialized: now 1786515511419755 us; error 0 us; skew 500 ppm
I20260812 06:18:31.420742  4987 webserver.cc:533] Webserver started at http://127.4.222.193:41151/ using document root <none> and password file <none>
I20260812 06:18:31.420957  4987 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:31.421039  4987 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:31.421123  4987 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:31.421561  4987 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/instance:
uuid: "6a7c2773fafa4fc781e73b3372069467"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-zpfg"
I20260812 06:18:31.423399  4987 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:31.424625  5277 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:31.425004  4987 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:31.425101  4987 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root
uuid: "6a7c2773fafa4fc781e73b3372069467"
format_stamp: "Formatted at 2026-08-12 06:18:31 on dist-test-slave-zpfg"
I20260812 06:18:31.425195  4987 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-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:31.438097  4987 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:31.438653  4987 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:31.439000  4987 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:31.439597  4987 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:31.439672  4987 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:31.439731  4987 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:31.439782  4987 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:31.444267  4987 rpc_server.cc:307] RPC server started. Bound to: 127.4.222.193:34659
I20260812 06:18:31.444940  5341 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.222.193:34659 every 8 connection(s)
I20260812 06:18:31.456131  5342 heartbeater.cc:344] Connected to a master server at 127.4.222.254:33021
I20260812 06:18:31.456286  5342 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:31.456547  5342 heartbeater.cc:507] Master 127.4.222.254:33021 requested a full tablet report, sending...
I20260812 06:18:31.457360  5212 ts_manager.cc:194] Registered new tserver with Master: 6a7c2773fafa4fc781e73b3372069467 (127.4.222.193:34659)
I20260812 06:18:31.458237  5212 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46070
I20260812 06:18:31.458416  4987 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013354399s
I20260812 06:18:31.466079  5212 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46072:
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:31.476053  5306 tablet_service.cc:1511] Processing CreateTablet for tablet 4304c6b70ab9405b8e5a148946bb7539 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8b256a0fca234cc1a21001e3ce60294d]), partition=
I20260812 06:18:31.476387  5306 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4304c6b70ab9405b8e5a148946bb7539. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:31.478466  5355 tablet_bootstrap.cc:492] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Bootstrap starting.
I20260812 06:18:31.479260  5355 tablet_bootstrap.cc:654] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:31.480327  5355 tablet_bootstrap.cc:492] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: No bootstrap required, opened a new log
I20260812 06:18:31.480502  5355 ts_tablet_manager.cc:1403] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:31.480922  5355 raft_consensus.cc:359] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a7c2773fafa4fc781e73b3372069467" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 34659 } }
I20260812 06:18:31.481040  5355 raft_consensus.cc:385] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:31.481088  5355 raft_consensus.cc:740] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6a7c2773fafa4fc781e73b3372069467, State: Initialized, Role: FOLLOWER
I20260812 06:18:31.481235  5355 consensus_queue.cc:260] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [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: "6a7c2773fafa4fc781e73b3372069467" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 34659 } }
I20260812 06:18:31.481345  5355 raft_consensus.cc:399] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:31.481383  5355 raft_consensus.cc:493] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:31.481426  5355 raft_consensus.cc:3060] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:31.482194  5355 raft_consensus.cc:515] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a7c2773fafa4fc781e73b3372069467" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 34659 } }
I20260812 06:18:31.482402  5355 leader_election.cc:304] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [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: 6a7c2773fafa4fc781e73b3372069467; no voters: 
I20260812 06:18:31.482631  5355 leader_election.cc:290] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:31.482931  5358 raft_consensus.cc:2804] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:31.482998  5355 ts_tablet_manager.cc:1434] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:31.483220  5342 heartbeater.cc:499] Master 127.4.222.254:33021 was elected leader, sending a full tablet report...
I20260812 06:18:31.483249  5358 raft_consensus.cc:697] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 1 LEADER]: Becoming Leader. State: Replica: 6a7c2773fafa4fc781e73b3372069467, State: Running, Role: LEADER
I20260812 06:18:31.483404  5358 consensus_queue.cc:237] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [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: "6a7c2773fafa4fc781e73b3372069467" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 34659 } }
I20260812 06:18:31.484750  5212 catalog_manager.cc:5719] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6a7c2773fafa4fc781e73b3372069467 (127.4.222.193). New cstate: current_term: 1 leader_uuid: "6a7c2773fafa4fc781e73b3372069467" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a7c2773fafa4fc781e73b3372069467" member_type: VOTER last_known_addr { host: "127.4.222.193" port: 34659 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:31.545846  4987 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.018s	sys 0.004s
I20260812 06:18:31.695835  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539): perf score=19.054940
I20260812 06:18:31.876708  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.180s	user 0.142s	sys 0.036s Metrics: {"bytes_written":12512610,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":920,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43496,"lbm_writes_lt_1ms":762,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":13696,"update_count":1525}
I20260812 06:18:31.877475  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling LogGCOp(4304c6b70ab9405b8e5a148946bb7539): free 20743880 bytes of WAL
I20260812 06:18:31.877756  5282 log_reader.cc:385] T 4304c6b70ab9405b8e5a148946bb7539: removed 2 log segments from log reader
I20260812 06:18:31.877833  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000001 (ops 1-6)
I20260812 06:18:31.877928  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000002 (ops 7-11)
I20260812 06:18:31.883040  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: LogGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:31.883528  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539): 16411393 bytes on disk
I20260812 06:18:31.884143  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.884702  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:31.910912  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.026s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4528,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:31.911378  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:31.922508  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.923038  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:32.118021  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.195s	user 0.135s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":456,"lbm_read_time_us":11943,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29678,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":316,"threads_started":5,"update_count":2500}
I20260812 06:18:32.118656  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:32.183580  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.065s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21799,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.184159  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:32.195698  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.196276  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:32.398525  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.202s	user 0.139s	sys 0.055s 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":396,"lbm_read_time_us":14509,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31444,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73088,"update_count":2500}
I20260812 06:18:32.399240  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=11.118625
I20260812 06:18:32.440737  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.441285  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:32.462082  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.021s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.462781  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:32.484617  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.022s	user 0.009s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3952,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.485323  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:32.676309  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.191s	user 0.114s	sys 0.071s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":225,"lbm_read_time_us":14161,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28062,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":94208,"update_count":2500}
I20260812 06:18:32.676985  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:32.734989  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.058s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23658,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:32.735493  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:32.747706  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.748490  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:32.925508  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.177s	user 0.109s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":685,"lbm_read_time_us":11123,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28029,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25600,"update_count":2500}
I20260812 06:18:32.926200  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:32.973698  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.047s	user 0.036s	sys 0.005s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18818,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.974262  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:32.986925  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.987440  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:33.158874  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.171s	user 0.114s	sys 0.047s 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":470,"lbm_read_time_us":11878,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33276,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:33.159578  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:33.215512  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.056s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18488,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.216182  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:33.227830  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.228375  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:33.263383  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1634,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1852,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:33.264022  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling LogGCOp(4304c6b70ab9405b8e5a148946bb7539): free 116849521 bytes of WAL
I20260812 06:18:33.264268  5282 log_reader.cc:385] T 4304c6b70ab9405b8e5a148946bb7539: removed 12 log segments from log reader
I20260812 06:18:33.264340  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000003 (ops 12-16)
I20260812 06:18:33.264402  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000004 (ops 17-21)
I20260812 06:18:33.264465  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000005 (ops 22-26)
I20260812 06:18:33.264510  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000006 (ops 27-30)
I20260812 06:18:33.264554  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000007 (ops 31-35)
I20260812 06:18:33.264595  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000008 (ops 36-40)
I20260812 06:18:33.264635  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000009 (ops 41-44)
I20260812 06:18:33.264678  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000010 (ops 45-49)
I20260812 06:18:33.264719  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000011 (ops 50-54)
I20260812 06:18:33.264760  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000012 (ops 55-58)
I20260812 06:18:33.264801  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000013 (ops 59-63)
I20260812 06:18:33.264842  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000014 (ops 64-68)
I20260812 06:18:33.292275  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: LogGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:33.292716  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=3.181125
I20260812 06:18:33.305631  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5336,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:33.306115  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling LogGCOp(4304c6b70ab9405b8e5a148946bb7539): free 11564875 bytes of WAL
I20260812 06:18:33.306489  5282 log_reader.cc:385] T 4304c6b70ab9405b8e5a148946bb7539: removed 1 log segments from log reader
I20260812 06:18:33.306557  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000015 (ops 69-72)
I20260812 06:18:33.308948  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: LogGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:33.309262  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:33.330768  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.021s	user 0.005s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.331393  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:33.559715  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.228s	user 0.147s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1112,"lbm_read_time_us":14982,"lbm_reads_lt_1ms":766,"lbm_write_time_us":39644,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":52608,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:18:33.560442  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539): 472 bytes on disk
I20260812 06:18:33.560958  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.561632  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=18.063937
I20260812 06:18:33.622769  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.061s	user 0.042s	sys 0.019s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27859,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:33.623265  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:33.639394  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.639882  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:33.855201  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.215s	user 0.152s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":138,"lbm_read_time_us":14082,"lbm_reads_lt_1ms":668,"lbm_write_time_us":37109,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":3000}
I20260812 06:18:33.858925  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:33.905320  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.046s	user 0.026s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.905973  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:33.927687  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.022s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.928241  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:34.122094  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.194s	user 0.132s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":468,"lbm_read_time_us":11874,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34531,"lbm_writes_lt_1ms":543,"mutex_wait_us":101,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:34.122951  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:34.192524  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.068s	user 0.031s	sys 0.034s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22271,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.193272  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.221879  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.028s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:18:34.222427  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.233282  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.233812  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:34.454639  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.221s	user 0.156s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":616,"lbm_read_time_us":15453,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35081,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3000}
I20260812 06:18:34.455585  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=16.079562
I20260812 06:18:34.511919  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.056s	user 0.038s	sys 0.012s Metrics: {"bytes_written":17640627,"delete_count":0,"lbm_write_time_us":22614,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2150}
I20260812 06:18:34.512477  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.524394  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3282160,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:34.524915  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.535976  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.536496  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:34.767583  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.231s	user 0.150s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1370,"lbm_read_time_us":16593,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35005,"lbm_writes_lt_1ms":643,"mutex_wait_us":347,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":3000}
I20260812 06:18:34.768520  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=18.063937
I20260812 06:18:34.843364  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.075s	user 0.047s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33578,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:34.843942  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.855165  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4123,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.855999  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:34.889045  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1347,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1828,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:34.889813  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling LogGCOp(4304c6b70ab9405b8e5a148946bb7539): free 120553396 bytes of WAL
I20260812 06:18:34.890156  5282 log_reader.cc:385] T 4304c6b70ab9405b8e5a148946bb7539: removed 12 log segments from log reader
I20260812 06:18:34.890220  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000016 (ops 73-77)
I20260812 06:18:34.890260  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000017 (ops 78-82)
I20260812 06:18:34.890298  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000018 (ops 83-86)
I20260812 06:18:34.890362  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000019 (ops 87-91)
I20260812 06:18:34.890396  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000020 (ops 92-96)
I20260812 06:18:34.890426  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000021 (ops 97-101)
I20260812 06:18:34.890456  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000022 (ops 102-106)
I20260812 06:18:34.890489  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000023 (ops 107-111)
I20260812 06:18:34.890525  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000024 (ops 112-116)
I20260812 06:18:34.890549  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000025 (ops 117-120)
I20260812 06:18:34.890571  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000026 (ops 121-125)
I20260812 06:18:34.890600  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000027 (ops 126-130)
I20260812 06:18:34.920740  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: LogGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:34.921314  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.941725  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":500}
I20260812 06:18:34.942189  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539): 483 bytes on disk
I20260812 06:18:34.942651  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.943143  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:34.953692  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.954139  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:35.215076  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.261s	user 0.197s	sys 0.063s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082165,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":916,"lbm_read_time_us":18799,"lbm_reads_lt_1ms":874,"lbm_write_time_us":48140,"lbm_writes_lt_1ms":843,"mutex_wait_us":91,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":21888,"thread_start_us":82,"threads_started":1,"update_count":4000}
I20260812 06:18:35.216687  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=18.063937
I20260812 06:18:35.290607  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.072s	user 0.040s	sys 0.027s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29890,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.291133  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=3.181125
I20260812 06:18:35.304672  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5579,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:35.305146  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:35.316404  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.317155  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:35.520669  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.203s	user 0.159s	sys 0.042s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979625,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":577,"lbm_read_time_us":14220,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41353,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":3500}
I20260812 06:18:35.521416  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=15.087375
I20260812 06:18:35.574061  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.052s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23030,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:35.574791  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:35.588474  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4765,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.588932  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:35.738178  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.149s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":133,"lbm_read_time_us":8572,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28982,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:35.738955  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:35.797318  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.058s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.797910  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:35.808735  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.809747  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:35.994110  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.184s	user 0.138s	sys 0.040s 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":427,"lbm_read_time_us":12118,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29046,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:35.994783  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:36.049078  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.054s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24140,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.049796  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:36.218555  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.169s	user 0.094s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1871,"lbm_read_time_us":12618,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25679,"lbm_writes_lt_1ms":443,"mutex_wait_us":352,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:36.219357  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=14.095187
I20260812 06:18:36.268523  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.049s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.269142  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=2.188937
I20260812 06:18:36.295447  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.026s	user 0.015s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.296083  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:36.335675  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushMRSOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.039s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1467,"drs_written":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2517,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:36.336494  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling LogGCOp(4304c6b70ab9405b8e5a148946bb7539): free 121006640 bytes of WAL
I20260812 06:18:36.336802  5282 log_reader.cc:385] T 4304c6b70ab9405b8e5a148946bb7539: removed 12 log segments from log reader
I20260812 06:18:36.336894  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000028 (ops 131-135)
I20260812 06:18:36.336994  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000029 (ops 136-140)
I20260812 06:18:36.337042  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000030 (ops 141-145)
I20260812 06:18:36.337105  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000031 (ops 146-150)
I20260812 06:18:36.337157  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000032 (ops 151-155)
I20260812 06:18:36.337183  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000033 (ops 156-160)
I20260812 06:18:36.337206  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000034 (ops 161-165)
I20260812 06:18:36.337239  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000035 (ops 166-170)
I20260812 06:18:36.337268  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000036 (ops 171-174)
I20260812 06:18:36.337299  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000037 (ops 175-179)
I20260812 06:18:36.337335  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000038 (ops 180-184)
I20260812 06:18:36.337357  5282 log.cc:1079] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: Deleting log segment in path: /tmp/dist-test-taskc0GPP8/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515505805645-4987-0/minicluster-data/ts-0-root/wals/4304c6b70ab9405b8e5a148946bb7539/wal-000000039 (ops 185-189)
I20260812 06:18:36.362912  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: LogGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:36.363334  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539): 461 bytes on disk
I20260812 06:18:36.363801  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: UndoDeltaBlockGCOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.364349  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=6.157687
I20260812 06:18:36.392297  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.028s	user 0.019s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10875,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:36.392935  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:36.611903  4987 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.066s	user 1.899s	sys 0.160s
I20260812 06:18:36.633469  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.240s	user 0.162s	sys 0.075s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979632,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":17277,"lbm_reads_lt_1ms":761,"lbm_write_time_us":40879,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3500}
I20260812 06:18:36.634030  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539): perf score=18.063937
I20260812 06:18:36.675722  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: FlushDeltaMemStoresOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":20432,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:36.676533  5343 maintenance_manager.cc:419] P 6a7c2773fafa4fc781e73b3372069467: Scheduling MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539): perf score=1.000000
I20260812 06:18:36.737033  4987 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.125s	user 0.002s	sys 0.000s
I20260812 06:18:36.737744  4987 tablet_server.cc:179] TabletServer@127.4.222.193:0 shutting down...
I20260812 06:18:36.846544  5282 maintenance_manager.cc:643] P 6a7c2773fafa4fc781e73b3372069467: MajorDeltaCompactionOp(4304c6b70ab9405b8e5a148946bb7539) complete. Timing: real 0.170s	user 0.117s	sys 0.052s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774575,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":409,"lbm_read_time_us":11997,"lbm_reads_lt_1ms":567,"lbm_write_time_us":37873,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":541,"mutex_wait_us":125,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:36.847373  4987 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:36.847708  4987 tablet_replica.cc:333] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467: stopping tablet replica
I20260812 06:18:36.847868  4987 raft_consensus.cc:2243] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:36.848047  4987 raft_consensus.cc:2272] T 4304c6b70ab9405b8e5a148946bb7539 P 6a7c2773fafa4fc781e73b3372069467 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:36.853299  4987 tablet_server.cc:196] TabletServer@127.4.222.193:0 shutdown complete.
I20260812 06:18:36.894209  4987 master.cc:562] Master@127.4.222.254:33021 shutting down...
I20260812 06:18:36.897949  4987 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:36.898128  4987 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:36.898173  4987 tablet_replica.cc:333] T 00000000000000000000000000000000 P 294bb9e5669841389504fed701b5169b: stopping tablet replica
I20260812 06:18:36.910898  4987 master.cc:584] Master@127.4.222.254:33021 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5667 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11183 ms total)

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