[==========] 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:16:52.477835  5823 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.175.254:43751
I20260812 06:16:52.478778  5823 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:16:52.479332  5823 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:52.485221  5832 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:16:52.485325  5823 server_base.cc:1061] running on GCE node
W20260812 06:16:52.485244  5838 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:16:52.485487  5836 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:16:52.486025  5823 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:52.486130  5823 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:16:52.486173  5823 hybrid_clock.cc:648] HybridClock initialized: now 1786515412486171 us; error 0 us; skew 500 ppm
I20260812 06:16:52.487946  5823 webserver.cc:533] Webserver started at http://127.5.175.254:36011/ using document root <none> and password file <none>
I20260812 06:16:52.488447  5823 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:52.488511  5823 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:52.488722  5823 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:52.490407  5823 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/master-0-root/instance:
uuid: "aa63da1e4dc14f0097b9e46660f9f19c"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-7lbf"
I20260812 06:16:52.493727  5823 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:52.495808  5845 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:16:52.496758  5823 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:52.496862  5823 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/master-0-root
uuid: "aa63da1e4dc14f0097b9e46660f9f19c"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-7lbf"
I20260812 06:16:52.496945  5823 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-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:16:52.527740  5823 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:52.528338  5823 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:16:52.528514  5823 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:52.535737  5942 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.175.254:43751 every 8 connection(s)
I20260812 06:16:52.535738  5823 rpc_server.cc:307] RPC server started. Bound to: 127.5.175.254:43751
I20260812 06:16:52.538003  5944 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:16:52.543170  5944 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c: Bootstrap starting.
I20260812 06:16:52.545392  5944 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:52.546273  5944 log.cc:826] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:52.547794  5944 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c: No bootstrap required, opened a new log
I20260812 06:16:52.550549  5944 raft_consensus.cc:359] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa63da1e4dc14f0097b9e46660f9f19c" member_type: VOTER }
I20260812 06:16:52.550707  5944 raft_consensus.cc:385] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:52.550771  5944 raft_consensus.cc:740] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aa63da1e4dc14f0097b9e46660f9f19c, State: Initialized, Role: FOLLOWER
I20260812 06:16:52.551333  5944 consensus_queue.cc:260] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [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: "aa63da1e4dc14f0097b9e46660f9f19c" member_type: VOTER }
I20260812 06:16:52.551477  5944 raft_consensus.cc:399] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:52.551543  5944 raft_consensus.cc:493] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:52.551664  5944 raft_consensus.cc:3060] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:52.552390  5944 raft_consensus.cc:515] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa63da1e4dc14f0097b9e46660f9f19c" member_type: VOTER }
I20260812 06:16:52.552796  5944 leader_election.cc:304] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [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: aa63da1e4dc14f0097b9e46660f9f19c; no voters: 
I20260812 06:16:52.553085  5944 leader_election.cc:290] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:52.553195  5950 raft_consensus.cc:2804] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:52.553414  5950 raft_consensus.cc:697] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 1 LEADER]: Becoming Leader. State: Replica: aa63da1e4dc14f0097b9e46660f9f19c, State: Running, Role: LEADER
I20260812 06:16:52.553808  5950 consensus_queue.cc:237] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [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: "aa63da1e4dc14f0097b9e46660f9f19c" member_type: VOTER }
I20260812 06:16:52.554046  5944 sys_catalog.cc:565] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:52.555642  5953 sys_catalog.cc:455] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [sys.catalog]: SysCatalogTable state changed. Reason: New leader aa63da1e4dc14f0097b9e46660f9f19c. Latest consensus state: current_term: 1 leader_uuid: "aa63da1e4dc14f0097b9e46660f9f19c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa63da1e4dc14f0097b9e46660f9f19c" member_type: VOTER } }
I20260812 06:16:52.555776  5953 sys_catalog.cc:458] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:52.555670  5952 sys_catalog.cc:455] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "aa63da1e4dc14f0097b9e46660f9f19c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa63da1e4dc14f0097b9e46660f9f19c" member_type: VOTER } }
I20260812 06:16:52.556005  5952 sys_catalog.cc:458] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:52.556082  5974 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:52.556236  5823 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:52.558331  5974 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:52.562582  5974 catalog_manager.cc:1383] Generated new cluster ID: 37f16ae5ee674f289b68cd06226c7afe
I20260812 06:16:52.562647  5974 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:52.590512  5974 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:52.591356  5974 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:52.597213  5974 catalog_manager.cc:6092] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c: Generated new TSK 0
I20260812 06:16:52.597834  5974 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:52.620885  5823 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:52.623661  5980 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:16:52.623696  5984 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:16:52.623888  5981 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:16:52.624316  5823 server_base.cc:1061] running on GCE node
I20260812 06:16:52.624486  5823 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:52.624531  5823 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:16:52.624547  5823 hybrid_clock.cc:648] HybridClock initialized: now 1786515412624547 us; error 0 us; skew 500 ppm
I20260812 06:16:52.625373  5823 webserver.cc:533] Webserver started at http://127.5.175.193:46173/ using document root <none> and password file <none>
I20260812 06:16:52.625561  5823 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:52.625622  5823 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:52.625706  5823 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:52.626078  5823 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/instance:
uuid: "22fffae4dd794e5782d02ba781c4c782"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-7lbf"
I20260812 06:16:52.627444  5823 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:52.628341  5992 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:16:52.628571  5823 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:52.628635  5823 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root
uuid: "22fffae4dd794e5782d02ba781c4c782"
format_stamp: "Formatted at 2026-08-12 06:16:52 on dist-test-slave-7lbf"
I20260812 06:16:52.628680  5823 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-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:16:52.641876  5823 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:52.642280  5823 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:52.642745  5823 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:52.643576  5823 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:52.643628  5823 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:52.643672  5823 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:52.643702  5823 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:52.649853  5823 rpc_server.cc:307] RPC server started. Bound to: 127.5.175.193:39351
I20260812 06:16:52.650005  6101 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.175.193:39351 every 8 connection(s)
I20260812 06:16:52.663059  6102 heartbeater.cc:344] Connected to a master server at 127.5.175.254:43751
I20260812 06:16:52.663313  6102 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:52.663731  6102 heartbeater.cc:507] Master 127.5.175.254:43751 requested a full tablet report, sending...
I20260812 06:16:52.665074  5877 ts_manager.cc:194] Registered new tserver with Master: 22fffae4dd794e5782d02ba781c4c782 (127.5.175.193:39351)
I20260812 06:16:52.665151  5823 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014633101s
I20260812 06:16:52.666280  5877 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58110
I20260812 06:16:52.674402  5877 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58126:
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:16:52.687714  6048 tablet_service.cc:1511] Processing CreateTablet for tablet a3b5e6c9019d421789a7ef1544d6d758 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7f706547a2624adc940c53cf1a3f4f5f]), partition=
I20260812 06:16:52.688160  6048 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a3b5e6c9019d421789a7ef1544d6d758. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:52.690429  6123 tablet_bootstrap.cc:492] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Bootstrap starting.
I20260812 06:16:52.691852  6123 tablet_bootstrap.cc:654] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:52.693142  6123 tablet_bootstrap.cc:492] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: No bootstrap required, opened a new log
I20260812 06:16:52.693249  6123 ts_tablet_manager.cc:1403] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:52.693837  6123 raft_consensus.cc:359] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "22fffae4dd794e5782d02ba781c4c782" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 39351 } }
I20260812 06:16:52.694029  6123 raft_consensus.cc:385] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:52.694115  6123 raft_consensus.cc:740] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 22fffae4dd794e5782d02ba781c4c782, State: Initialized, Role: FOLLOWER
I20260812 06:16:52.694263  6123 consensus_queue.cc:260] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [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: "22fffae4dd794e5782d02ba781c4c782" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 39351 } }
I20260812 06:16:52.694379  6123 raft_consensus.cc:399] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:52.694427  6123 raft_consensus.cc:493] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:52.694475  6123 raft_consensus.cc:3060] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:52.695443  6123 raft_consensus.cc:515] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "22fffae4dd794e5782d02ba781c4c782" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 39351 } }
I20260812 06:16:52.695597  6123 leader_election.cc:304] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [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: 22fffae4dd794e5782d02ba781c4c782; no voters: 
I20260812 06:16:52.695822  6123 leader_election.cc:290] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:52.695940  6125 raft_consensus.cc:2804] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:52.696171  6123 ts_tablet_manager.cc:1434] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:52.696203  6125 raft_consensus.cc:697] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 1 LEADER]: Becoming Leader. State: Replica: 22fffae4dd794e5782d02ba781c4c782, State: Running, Role: LEADER
I20260812 06:16:52.696394  6102 heartbeater.cc:499] Master 127.5.175.254:43751 was elected leader, sending a full tablet report...
I20260812 06:16:52.696404  6125 consensus_queue.cc:237] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [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: "22fffae4dd794e5782d02ba781c4c782" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 39351 } }
I20260812 06:16:52.698935  5877 catalog_manager.cc:5719] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 reported cstate change: term changed from 0 to 1, leader changed from <none> to 22fffae4dd794e5782d02ba781c4c782 (127.5.175.193). New cstate: current_term: 1 leader_uuid: "22fffae4dd794e5782d02ba781c4c782" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "22fffae4dd794e5782d02ba781c4c782" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 39351 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:52.761790  5823 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.024s	sys 0.004s
I20260812 06:16:52.901141  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=19.054940
I20260812 06:16:53.066968  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.165s	user 0.118s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":256,"delete_count":0,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1088,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41993,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":153,"threads_started":1,"update_count":1500}
I20260812 06:16:53.068161  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling LogGCOp(a3b5e6c9019d421789a7ef1544d6d758): free 20743880 bytes of WAL
I20260812 06:16:53.068504  6002 log_reader.cc:385] T a3b5e6c9019d421789a7ef1544d6d758: removed 2 log segments from log reader
I20260812 06:16:53.068593  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000001 (ops 1-6)
I20260812 06:16:53.068667  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000002 (ops 7-11)
I20260812 06:16:53.073872  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: LogGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:53.074340  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:53.107297  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.033s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.107771  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:53.117852  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.118254  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758): 16411394 bytes on disk
I20260812 06:16:53.118841  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:16:53.119235  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:53.275677  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.156s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":495,"lbm_read_time_us":12311,"lbm_reads_lt_1ms":569,"lbm_write_time_us":25072,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":283,"threads_started":5,"update_count":2500}
I20260812 06:16:53.276137  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=10.126437
I20260812 06:16:53.316622  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.040s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14111,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.317067  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:53.332245  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.332902  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:53.452275  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.119s	user 0.090s	sys 0.026s 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":674,"lbm_read_time_us":9690,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20720,"lbm_writes_lt_1ms":443,"mutex_wait_us":341,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.452767  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=10.126437
I20260812 06:16:53.484616  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13256,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.485205  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:53.594830  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.109s	user 0.078s	sys 0.031s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":257,"lbm_read_time_us":7759,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18468,"lbm_writes_lt_1ms":343,"mutex_wait_us":38,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":1500}
I20260812 06:16:53.595338  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=10.126437
I20260812 06:16:53.625165  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.030s	user 0.015s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:53.625718  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:53.754614  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.129s	user 0.083s	sys 0.040s 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":127,"lbm_read_time_us":7888,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22054,"lbm_writes_lt_1ms":343,"mutex_wait_us":23,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":1500}
I20260812 06:16:53.755127  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=10.126437
I20260812 06:16:53.796875  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.042s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13619,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":413568,"update_count":1500}
I20260812 06:16:53.797322  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:53.808040  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.808609  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:53.923739  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.115s	user 0.091s	sys 0.024s 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":284,"lbm_read_time_us":8104,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22413,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:16:53.924397  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=10.126437
I20260812 06:16:53.965780  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.041s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14255,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:16:53.966255  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:53.977123  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.977698  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:54.110872  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.133s	user 0.100s	sys 0.029s 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":92,"lbm_read_time_us":9778,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25163,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:54.111357  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=10.126437
I20260812 06:16:54.170946  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.059s	user 0.017s	sys 0.034s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19366,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.171482  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:54.186681  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.187264  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:54.337159  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.150s	user 0.102s	sys 0.046s 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":194,"lbm_read_time_us":11094,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22613,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:16:54.337759  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=7.149875
I20260812 06:16:54.370100  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11807,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:54.371538  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:54.383368  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:54.383800  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:54.411420  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1274,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1337,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:54.412401  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling LogGCOp(a3b5e6c9019d421789a7ef1544d6d758): free 124710292 bytes of WAL
I20260812 06:16:54.412670  6002 log_reader.cc:385] T a3b5e6c9019d421789a7ef1544d6d758: removed 12 log segments from log reader
I20260812 06:16:54.412724  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000003 (ops 12-16)
I20260812 06:16:54.412762  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000004 (ops 17-21)
I20260812 06:16:54.412822  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000005 (ops 22-26)
I20260812 06:16:54.412848  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000006 (ops 27-31)
I20260812 06:16:54.412879  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000007 (ops 32-36)
I20260812 06:16:54.412910  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000008 (ops 37-41)
I20260812 06:16:54.412940  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000009 (ops 42-46)
I20260812 06:16:54.412971  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000010 (ops 47-51)
I20260812 06:16:54.412999  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000011 (ops 52-56)
I20260812 06:16:54.413029  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000012 (ops 57-61)
I20260812 06:16:54.413059  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000013 (ops 62-66)
I20260812 06:16:54.413089  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000014 (ops 67-71)
I20260812 06:16:54.437346  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: LogGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:54.437876  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758): 472 bytes on disk
I20260812 06:16:54.438370  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.439026  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=5.165500
I20260812 06:16:54.454728  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":6309,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:16:54.455163  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:54.463969  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.009s	user 0.000s	sys 0.006s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":2366,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:16:54.464537  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:54.640596  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.175s	user 0.135s	sys 0.028s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24774851,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1048,"lbm_read_time_us":11638,"lbm_reads_lt_1ms":566,"lbm_write_time_us":26197,"lbm_writes_lt_1ms":543,"mutex_wait_us":513,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":76,"threads_started":1,"update_count":2500}
I20260812 06:16:54.641181  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:54.693609  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.052s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24259,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.694118  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:54.712258  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.018s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.712797  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:54.877887  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.165s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":316,"lbm_read_time_us":10655,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31555,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:54.878495  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:54.925271  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19866,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.925877  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:54.942267  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.942741  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:55.102411  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.159s	user 0.111s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":8606,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31567,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:16:55.102964  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:55.149179  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.046s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20441,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.149780  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:55.165786  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.166337  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:55.318876  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.152s	user 0.131s	sys 0.012s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":10591,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26672,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:16:55.319511  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:55.370805  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.051s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20460,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.371296  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:55.381791  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.382427  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:55.530246  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.148s	user 0.120s	sys 0.023s 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":994,"lbm_read_time_us":8650,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28511,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:16:55.531015  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=11.118625
I20260812 06:16:55.564100  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.033s	user 0.022s	sys 0.008s Metrics: {"bytes_written":13251051,"delete_count":0,"lbm_write_time_us":13599,"lbm_writes_lt_1ms":326,"reinsert_count":0,"update_count":1615}
I20260812 06:16:55.564723  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.196750
I20260812 06:16:55.589668  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":4567,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:16:55.590204  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:55.601600  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.602404  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:55.769170  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.167s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774789,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":524,"lbm_read_time_us":11733,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34424,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:16:55.769811  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:55.827365  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.057s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19853,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.827957  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:55.838024  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3801,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.838629  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:55.872154  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1570,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1900,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:55.872862  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling LogGCOp(a3b5e6c9019d421789a7ef1544d6d758): free 133024409 bytes of WAL
I20260812 06:16:55.873097  6002 log_reader.cc:385] T a3b5e6c9019d421789a7ef1544d6d758: removed 13 log segments from log reader
I20260812 06:16:55.873143  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000015 (ops 72-76)
I20260812 06:16:55.873171  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000016 (ops 77-81)
I20260812 06:16:55.873201  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000017 (ops 82-86)
I20260812 06:16:55.873232  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000018 (ops 87-91)
I20260812 06:16:55.873265  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000019 (ops 92-96)
I20260812 06:16:55.873301  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000020 (ops 97-100)
I20260812 06:16:55.873335  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000021 (ops 101-105)
I20260812 06:16:55.873358  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000022 (ops 106-110)
I20260812 06:16:55.873389  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000023 (ops 111-115)
I20260812 06:16:55.873414  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000024 (ops 116-120)
I20260812 06:16:55.873446  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000025 (ops 121-125)
I20260812 06:16:55.873505  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000026 (ops 126-130)
I20260812 06:16:55.873569  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000027 (ops 131-135)
I20260812 06:16:55.896615  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: LogGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:55.896982  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758): 492 bytes on disk
I20260812 06:16:55.897441  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:16:55.897950  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=3.181125
I20260812 06:16:55.914932  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6761,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:55.915328  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:55.924485  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3301,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:55.924907  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:56.122051  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.197s	user 0.135s	sys 0.058s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":688,"lbm_read_time_us":13843,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33499,"lbm_writes_lt_1ms":743,"mutex_wait_us":194,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:16:56.122637  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=15.087375
I20260812 06:16:56.173906  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.051s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":19814,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:56.174454  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:56.186792  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.187256  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:56.196381  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3340,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:56.196834  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:56.356616  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.160s	user 0.130s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":268,"lbm_read_time_us":10480,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35084,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:16:56.357121  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:56.402102  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.045s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18375,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.402665  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:56.418390  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.419003  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:56.571717  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.152s	user 0.116s	sys 0.030s 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":238,"lbm_read_time_us":9068,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29583,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":47104,"update_count":2500}
I20260812 06:16:56.572356  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=11.118625
I20260812 06:16:56.617043  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.045s	user 0.012s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19455,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:56.617558  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:56.639147  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.021s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:16:56.639607  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:56.649179  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":3471,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:16:56.649703  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:56.821935  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.172s	user 0.119s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1079,"lbm_read_time_us":12020,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25276,"lbm_writes_lt_1ms":543,"mutex_wait_us":789,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2500}
I20260812 06:16:56.822443  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:56.881687  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.059s	user 0.017s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23113,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.882215  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:56.896812  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.897509  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:57.065636  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.168s	user 0.135s	sys 0.023s 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":621,"lbm_read_time_us":12428,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27325,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:16:57.066144  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:57.110801  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.044s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19288,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.111317  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:57.121592  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.122419  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:57.150290  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushMRSOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.028s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1293,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1311,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:57.150936  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling LogGCOp(a3b5e6c9019d421789a7ef1544d6d758): free 112239559 bytes of WAL
I20260812 06:16:57.151149  6002 log_reader.cc:385] T a3b5e6c9019d421789a7ef1544d6d758: removed 11 log segments from log reader
I20260812 06:16:57.151196  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000028 (ops 136-140)
I20260812 06:16:57.151224  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000029 (ops 141-145)
I20260812 06:16:57.151253  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000030 (ops 146-150)
I20260812 06:16:57.151283  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000031 (ops 151-155)
I20260812 06:16:57.151316  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000032 (ops 156-160)
I20260812 06:16:57.151350  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000033 (ops 161-165)
I20260812 06:16:57.151382  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000034 (ops 166-170)
I20260812 06:16:57.151417  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000035 (ops 171-174)
I20260812 06:16:57.151448  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000036 (ops 175-179)
I20260812 06:16:57.151480  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000037 (ops 180-184)
I20260812 06:16:57.151515  6002 log.cc:1079] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/a3b5e6c9019d421789a7ef1544d6d758/wal-000000038 (ops 185-189)
I20260812 06:16:57.170117  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: LogGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.019s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:16:57.170598  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:57.190657  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.020s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.191133  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758): 447 bytes on disk
I20260812 06:16:57.191568  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: UndoDeltaBlockGCOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.192080  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=2.188937
I20260812 06:16:57.206370  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.206893  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=1.000000
I20260812 06:16:57.378675  5823 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.617s	user 1.714s	sys 0.106s
I20260812 06:16:57.405857  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: MajorDeltaCompactionOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.199s	user 0.147s	sys 0.052s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14062,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35612,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:16:57.406373  6103 maintenance_manager.cc:419] P 22fffae4dd794e5782d02ba781c4c782: Scheduling FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758): perf score=14.095187
I20260812 06:16:57.445731  5823 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.003s	sys 0.000s
I20260812 06:16:57.446329  5823 tablet_server.cc:179] TabletServer@127.5.175.193:0 shutting down...
I20260812 06:16:57.487778  6002 maintenance_manager.cc:643] P 22fffae4dd794e5782d02ba781c4c782: FlushDeltaMemStoresOp(a3b5e6c9019d421789a7ef1544d6d758) complete. Timing: real 0.081s	user 0.024s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":14251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.488487  5823 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:57.488895  5823 tablet_replica.cc:333] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782: stopping tablet replica
I20260812 06:16:57.489106  5823 raft_consensus.cc:2243] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:57.489307  5823 raft_consensus.cc:2272] T a3b5e6c9019d421789a7ef1544d6d758 P 22fffae4dd794e5782d02ba781c4c782 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:57.504308  5823 tablet_server.cc:196] TabletServer@127.5.175.193:0 shutdown complete.
I20260812 06:16:57.509038  5823 master.cc:562] Master@127.5.175.254:43751 shutting down...
I20260812 06:16:57.512398  5823 raft_consensus.cc:2243] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:57.512564  5823 raft_consensus.cc:2272] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:57.512622  5823 tablet_replica.cc:333] T 00000000000000000000000000000000 P aa63da1e4dc14f0097b9e46660f9f19c: stopping tablet replica
I20260812 06:16:57.524971  5823 master.cc:584] Master@127.5.175.254:43751 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5122 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:57.600503  5823 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.175.254:37433
I20260812 06:16:57.600912  5823 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:57.602815  6153 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:16:57.602921  6156 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:16:57.602957  6160 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:16:57.603175  5823 server_base.cc:1061] running on GCE node
I20260812 06:16:57.603341  5823 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:57.603384  5823 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:16:57.603399  5823 hybrid_clock.cc:648] HybridClock initialized: now 1786515417603399 us; error 0 us; skew 500 ppm
I20260812 06:16:57.604166  5823 webserver.cc:533] Webserver started at http://127.5.175.254:46027/ using document root <none> and password file <none>
I20260812 06:16:57.604324  5823 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:57.604368  5823 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:57.604424  5823 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:57.604805  5823 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/master-0-root/instance:
uuid: "0b5ca15b163d42128825be7d3e326681"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-7lbf"
I20260812 06:16:57.606343  5823 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:57.607226  6172 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:16:57.607440  5823 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:57.607511  5823 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/master-0-root
uuid: "0b5ca15b163d42128825be7d3e326681"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-7lbf"
I20260812 06:16:57.607586  5823 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-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:16:57.613193  5823 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:57.613597  5823 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:57.618654  5823 rpc_server.cc:307] RPC server started. Bound to: 127.5.175.254:37433
I20260812 06:16:57.628822  6272 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:16:57.635070  6271 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.175.254:37433 every 8 connection(s)
I20260812 06:16:57.636396  6272 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681: Bootstrap starting.
I20260812 06:16:57.637200  6272 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:57.638217  6272 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681: No bootstrap required, opened a new log
I20260812 06:16:57.638619  6272 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b5ca15b163d42128825be7d3e326681" member_type: VOTER }
I20260812 06:16:57.638705  6272 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:57.638741  6272 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0b5ca15b163d42128825be7d3e326681, State: Initialized, Role: FOLLOWER
I20260812 06:16:57.638885  6272 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [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: "0b5ca15b163d42128825be7d3e326681" member_type: VOTER }
I20260812 06:16:57.638957  6272 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:57.638983  6272 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:57.639030  6272 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:57.639722  6272 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b5ca15b163d42128825be7d3e326681" member_type: VOTER }
I20260812 06:16:57.639846  6272 leader_election.cc:304] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [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: 0b5ca15b163d42128825be7d3e326681; no voters: 
I20260812 06:16:57.640026  6272 leader_election.cc:290] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:57.640149  6278 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:57.640326  6278 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 1 LEADER]: Becoming Leader. State: Replica: 0b5ca15b163d42128825be7d3e326681, State: Running, Role: LEADER
I20260812 06:16:57.640527  6272 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:57.640460  6278 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [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: "0b5ca15b163d42128825be7d3e326681" member_type: VOTER }
I20260812 06:16:57.640929  6280 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0b5ca15b163d42128825be7d3e326681. Latest consensus state: current_term: 1 leader_uuid: "0b5ca15b163d42128825be7d3e326681" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b5ca15b163d42128825be7d3e326681" member_type: VOTER } }
I20260812 06:16:57.640902  6279 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0b5ca15b163d42128825be7d3e326681" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b5ca15b163d42128825be7d3e326681" member_type: VOTER } }
I20260812 06:16:57.641031  6280 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:57.641091  6279 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:57.641386  6285 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:57.642251  6285 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:57.642432  5823 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:57.644076  6285 catalog_manager.cc:1383] Generated new cluster ID: 8945f376eb064238b527cffac0b5b8fe
I20260812 06:16:57.644116  6285 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:57.650972  6285 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:57.651455  6285 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:57.655685  6285 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681: Generated new TSK 0
I20260812 06:16:57.655813  6285 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:57.658556  5823 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:57.660338  6307 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:16:57.660362  6306 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:16:57.660470  5823 server_base.cc:1061] running on GCE node
W20260812 06:16:57.660586  6310 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:16:57.660815  5823 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:57.660858  5823 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:16:57.660892  5823 hybrid_clock.cc:648] HybridClock initialized: now 1786515417660873 us; error 0 us; skew 500 ppm
I20260812 06:16:57.661681  5823 webserver.cc:533] Webserver started at http://127.5.175.193:45361/ using document root <none> and password file <none>
I20260812 06:16:57.661813  5823 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:57.661854  5823 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:57.661926  5823 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:57.662237  5823 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/instance:
uuid: "3cf9516e145d40e68b4773c0cd90b413"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-7lbf"
I20260812 06:16:57.663667  5823 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:57.664574  6316 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:16:57.664830  5823 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:57.664907  5823 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root
uuid: "3cf9516e145d40e68b4773c0cd90b413"
format_stamp: "Formatted at 2026-08-12 06:16:57 on dist-test-slave-7lbf"
I20260812 06:16:57.664980  5823 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-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:16:57.679409  5823 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:57.679780  5823 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:57.680086  5823 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:57.680562  5823 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:57.680603  5823 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:57.680648  5823 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:57.680676  5823 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:57.684594  5823 rpc_server.cc:307] RPC server started. Bound to: 127.5.175.193:46119
I20260812 06:16:57.684619  6440 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.175.193:46119 every 8 connection(s)
I20260812 06:16:57.692150  6441 heartbeater.cc:344] Connected to a master server at 127.5.175.254:37433
I20260812 06:16:57.692255  6441 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:57.692451  6441 heartbeater.cc:507] Master 127.5.175.254:37433 requested a full tablet report, sending...
I20260812 06:16:57.693049  6208 ts_manager.cc:194] Registered new tserver with Master: 3cf9516e145d40e68b4773c0cd90b413 (127.5.175.193:46119)
I20260812 06:16:57.693744  6208 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49798
I20260812 06:16:57.693774  5823 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008785117s
I20260812 06:16:57.700402  6208 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49814:
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:16:57.708237  6378 tablet_service.cc:1511] Processing CreateTablet for tablet 16f82fe4afc94c9e9884fdd943d1f889 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0f4706c36e6a45dfbf892cd6302c7b03]), partition=
I20260812 06:16:57.708544  6378 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 16f82fe4afc94c9e9884fdd943d1f889. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:57.710397  6463 tablet_bootstrap.cc:492] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Bootstrap starting.
I20260812 06:16:57.711293  6463 tablet_bootstrap.cc:654] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:57.712343  6463 tablet_bootstrap.cc:492] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: No bootstrap required, opened a new log
I20260812 06:16:57.712416  6463 ts_tablet_manager.cc:1403] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:57.712792  6463 raft_consensus.cc:359] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cf9516e145d40e68b4773c0cd90b413" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 46119 } }
I20260812 06:16:57.712883  6463 raft_consensus.cc:385] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:57.712924  6463 raft_consensus.cc:740] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3cf9516e145d40e68b4773c0cd90b413, State: Initialized, Role: FOLLOWER
I20260812 06:16:57.713045  6463 consensus_queue.cc:260] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [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: "3cf9516e145d40e68b4773c0cd90b413" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 46119 } }
I20260812 06:16:57.713111  6463 raft_consensus.cc:399] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:57.713145  6463 raft_consensus.cc:493] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:57.713195  6463 raft_consensus.cc:3060] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:57.714000  6463 raft_consensus.cc:515] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cf9516e145d40e68b4773c0cd90b413" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 46119 } }
I20260812 06:16:57.714131  6463 leader_election.cc:304] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [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: 3cf9516e145d40e68b4773c0cd90b413; no voters: 
I20260812 06:16:57.714318  6463 leader_election.cc:290] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:57.714407  6468 raft_consensus.cc:2804] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:57.714603  6463 ts_tablet_manager.cc:1434] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:57.714640  6468 raft_consensus.cc:697] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 1 LEADER]: Becoming Leader. State: Replica: 3cf9516e145d40e68b4773c0cd90b413, State: Running, Role: LEADER
I20260812 06:16:57.714630  6441 heartbeater.cc:499] Master 127.5.175.254:37433 was elected leader, sending a full tablet report...
I20260812 06:16:57.714829  6468 consensus_queue.cc:237] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [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: "3cf9516e145d40e68b4773c0cd90b413" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 46119 } }
I20260812 06:16:57.716042  6208 catalog_manager.cc:5719] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3cf9516e145d40e68b4773c0cd90b413 (127.5.175.193). New cstate: current_term: 1 leader_uuid: "3cf9516e145d40e68b4773c0cd90b413" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cf9516e145d40e68b4773c0cd90b413" member_type: VOTER last_known_addr { host: "127.5.175.193" port: 46119 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:57.771814  5823 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:16:57.935468  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=23.023690
I20260812 06:16:58.097213  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.161s	user 0.118s	sys 0.039s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":966,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45177,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":8704,"update_count":1500}
I20260812 06:16:58.098047  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling LogGCOp(16f82fe4afc94c9e9884fdd943d1f889): free 20743880 bytes of WAL
I20260812 06:16:58.098333  6324 log_reader.cc:385] T 16f82fe4afc94c9e9884fdd943d1f889: removed 2 log segments from log reader
I20260812 06:16:58.098387  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000001 (ops 1-6)
I20260812 06:16:58.098434  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000002 (ops 7-11)
I20260812 06:16:58.103658  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: LogGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:58.104082  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889): 20513813 bytes on disk
I20260812 06:16:58.104475  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:58.104882  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=3.181125
I20260812 06:16:58.126736  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.022s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":113,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":550}
I20260812 06:16:58.127164  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:58.140436  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4931,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.140961  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:58.335232  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.194s	user 0.112s	sys 0.077s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":484,"lbm_read_time_us":14137,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28199,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":328,"threads_started":5,"update_count":2500}
I20260812 06:16:58.335734  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=14.095187
I20260812 06:16:58.388833  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.053s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23037,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.389325  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:58.401782  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.402401  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:58.569850  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.167s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":80,"lbm_read_time_us":11970,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30000,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":53888,"update_count":2500}
I20260812 06:16:58.570387  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=14.095187
I20260812 06:16:58.618772  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.048s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19011,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.619266  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:58.629420  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.630017  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:58.779141  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.149s	user 0.117s	sys 0.022s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":11327,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25222,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:16:58.779815  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=14.095187
I20260812 06:16:58.829646  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.050s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24257,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.830129  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:58.840252  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.841003  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:59.010298  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.169s	user 0.133s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":706,"lbm_read_time_us":12014,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27105,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:16:59.011027  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=14.095187
I20260812 06:16:59.053088  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.042s	user 0.010s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18848,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.053615  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:59.190856  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.137s	user 0.064s	sys 0.069s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1084,"lbm_read_time_us":9268,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21400,"lbm_writes_lt_1ms":443,"mutex_wait_us":398,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:59.191444  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=11.118625
I20260812 06:16:59.226145  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.035s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14055,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:59.226655  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:59.249363  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.023s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.249851  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:59.259558  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.260128  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:59.297850  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.037s	user 0.020s	sys 0.007s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":1344,"drs_written":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2066,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:59.298453  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling LogGCOp(16f82fe4afc94c9e9884fdd943d1f889): free 121006426 bytes of WAL
I20260812 06:16:59.298667  6324 log_reader.cc:385] T 16f82fe4afc94c9e9884fdd943d1f889: removed 12 log segments from log reader
I20260812 06:16:59.298713  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000003 (ops 12-16)
I20260812 06:16:59.298743  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000004 (ops 17-21)
I20260812 06:16:59.298774  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000005 (ops 22-26)
I20260812 06:16:59.298803  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000006 (ops 27-30)
I20260812 06:16:59.298836  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000007 (ops 31-35)
I20260812 06:16:59.298869  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000008 (ops 36-40)
I20260812 06:16:59.298902  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000009 (ops 41-45)
I20260812 06:16:59.298944  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000010 (ops 46-50)
I20260812 06:16:59.298965  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000011 (ops 51-55)
I20260812 06:16:59.298996  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000012 (ops 56-60)
I20260812 06:16:59.299028  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000013 (ops 61-65)
I20260812 06:16:59.299059  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000014 (ops 66-70)
I20260812 06:16:59.319788  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: LogGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:16:59.320166  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:59.341889  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.022s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.342406  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889): 463 bytes on disk
I20260812 06:16:59.342803  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.343293  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:59.353171  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3696,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.353672  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:59.577816  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.224s	user 0.169s	sys 0.052s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020855,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":162,"lbm_read_time_us":14831,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35145,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:16:59.578357  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=18.063937
I20260812 06:16:59.643641  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.065s	user 0.026s	sys 0.024s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":23574,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:59.644102  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:16:59.655570  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:59.656257  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:16:59.865214  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.209s	user 0.119s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918094,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":659,"lbm_read_time_us":14691,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30992,"lbm_writes_lt_1ms":643,"mutex_wait_us":285,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:59.865778  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=16.079562
I20260812 06:16:59.929572  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.064s	user 0.020s	sys 0.036s Metrics: {"bytes_written":17722678,"delete_count":0,"lbm_write_time_us":29824,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2160}
I20260812 06:16:59.930055  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=5.165500
I20260812 06:16:59.953819  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.024s	user 0.019s	sys 0.001s Metrics: {"bytes_written":6892313,"delete_count":0,"lbm_write_time_us":8102,"lbm_writes_lt_1ms":171,"reinsert_count":0,"update_count":840}
I20260812 06:16:59.954353  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:00.165591  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.211s	user 0.132s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918108,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":16366,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33119,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":3000}
I20260812 06:17:00.166213  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=18.063937
I20260812 06:17:00.235064  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.069s	user 0.021s	sys 0.045s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30947,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:17:00.235515  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=3.181125
I20260812 06:17:00.256903  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.021s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6114,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:00.257395  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:00.266613  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3280,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.267190  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:00.472743  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.205s	user 0.131s	sys 0.074s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020620,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":166,"lbm_read_time_us":14629,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37075,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:17:00.473294  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=18.063937
I20260812 06:17:00.533447  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.060s	user 0.039s	sys 0.015s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24443,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:00.533941  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:00.555961  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.022s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.556499  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:00.571630  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.572247  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:00.600876  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.028s	user 0.020s	sys 0.003s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1318,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1378,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:00.601754  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling LogGCOp(16f82fe4afc94c9e9884fdd943d1f889): free 112239321 bytes of WAL
I20260812 06:17:00.601987  6324 log_reader.cc:385] T 16f82fe4afc94c9e9884fdd943d1f889: removed 11 log segments from log reader
I20260812 06:17:00.602049  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000015 (ops 71-74)
I20260812 06:17:00.602092  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000016 (ops 75-79)
I20260812 06:17:00.602125  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000017 (ops 80-84)
I20260812 06:17:00.602159  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000018 (ops 85-89)
I20260812 06:17:00.602186  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000019 (ops 90-94)
I20260812 06:17:00.602214  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000020 (ops 95-99)
I20260812 06:17:00.602242  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000021 (ops 100-104)
I20260812 06:17:00.602272  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000022 (ops 105-109)
I20260812 06:17:00.602303  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000023 (ops 110-114)
I20260812 06:17:00.602331  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000024 (ops 115-119)
I20260812 06:17:00.602358  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000025 (ops 120-124)
I20260812 06:17:00.627744  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: LogGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:00.628167  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=3.181125
I20260812 06:17:00.643029  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:00.643497  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889): 446 bytes on disk
I20260812 06:17:00.643896  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.644439  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:00.653906  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3442,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:00.654551  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:00.888118  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.233s	user 0.172s	sys 0.061s Metrics: {"cfile_cache_miss":935,"cfile_cache_miss_bytes":41225678,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":433,"lbm_read_time_us":15366,"lbm_reads_lt_1ms":975,"lbm_write_time_us":51886,"lbm_writes_lt_1ms":943,"mutex_wait_us":66,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":80,"threads_started":1,"update_count":4500}
I20260812 06:17:00.888809  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=18.063937
I20260812 06:17:00.960927  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.072s	user 0.032s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29443,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:17:00.961382  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=3.181125
I20260812 06:17:00.973178  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:00.973702  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:01.182135  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.208s	user 0.120s	sys 0.084s Metrics: {"cfile_cache_miss":642,"cfile_cache_miss_bytes":29328342,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":14739,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32283,"lbm_writes_lt_1ms":653,"mutex_wait_us":426,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":39936,"update_count":3050}
I20260812 06:17:01.182669  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=18.063937
I20260812 06:17:01.241313  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.058s	user 0.032s	sys 0.024s Metrics: {"bytes_written":20102074,"delete_count":0,"lbm_write_time_us":26097,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:17:01.241807  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:01.404942  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.163s	user 0.100s	sys 0.063s Metrics: {"cfile_cache_miss":521,"cfile_cache_miss_bytes":24405325,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":212,"lbm_read_time_us":11119,"lbm_reads_lt_1ms":553,"lbm_write_time_us":28633,"lbm_writes_lt_1ms":533,"mutex_wait_us":54,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":34816,"update_count":2450}
I20260812 06:17:01.405666  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=14.095187
I20260812 06:17:01.464985  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.059s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22507,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.465627  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:01.475984  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.476432  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:01.664619  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.188s	user 0.105s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":962,"lbm_read_time_us":12161,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31806,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:01.665158  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=14.095187
I20260812 06:17:01.719959  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.055s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24600,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.720530  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:01.740151  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.740981  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:01.929081  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.188s	user 0.118s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":13688,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29889,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:01.929701  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=15.087375
I20260812 06:17:01.986850  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.057s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":21561,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:17:01.987516  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=6.157687
I20260812 06:17:02.013705  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.026s	user 0.007s	sys 0.016s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9740,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:02.014258  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:02.044422  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushMRSOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.030s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1441,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1362,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:02.045146  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling LogGCOp(16f82fe4afc94c9e9884fdd943d1f889): free 120553620 bytes of WAL
I20260812 06:17:02.045385  6324 log_reader.cc:385] T 16f82fe4afc94c9e9884fdd943d1f889: removed 12 log segments from log reader
I20260812 06:17:02.045432  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000026 (ops 125-129)
I20260812 06:17:02.045461  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000027 (ops 130-134)
I20260812 06:17:02.045490  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000028 (ops 135-139)
I20260812 06:17:02.045540  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000029 (ops 140-144)
I20260812 06:17:02.045574  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000030 (ops 145-148)
I20260812 06:17:02.045591  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000031 (ops 149-153)
I20260812 06:17:02.045621  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000032 (ops 154-158)
I20260812 06:17:02.045655  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000033 (ops 159-163)
I20260812 06:17:02.045687  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000034 (ops 164-168)
I20260812 06:17:02.045720  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000035 (ops 169-172)
I20260812 06:17:02.045753  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000036 (ops 173-177)
I20260812 06:17:02.045784  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000037 (ops 178-182)
I20260812 06:17:02.066504  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: LogGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:02.066869  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=3.181125
I20260812 06:17:02.078864  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4841098,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:17:02.079342  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling LogGCOp(16f82fe4afc94c9e9884fdd943d1f889): free 12017897 bytes of WAL
I20260812 06:17:02.079558  6324 log_reader.cc:385] T 16f82fe4afc94c9e9884fdd943d1f889: removed 1 log segments from log reader
I20260812 06:17:02.079614  6324 log.cc:1079] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: Deleting log segment in path: /tmp/dist-test-taskNlJZbR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515412467524-5823-0/minicluster-data/ts-0-root/wals/16f82fe4afc94c9e9884fdd943d1f889/wal-000000038 (ops 183-187)
I20260812 06:17:02.082417  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: LogGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:02.082721  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:02.095237  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:17:02.095736  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889): 472 bytes on disk
I20260812 06:17:02.096200  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: UndoDeltaBlockGCOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.096897  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:02.338231  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.241s	user 0.173s	sys 0.067s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123143,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":286,"lbm_read_time_us":17817,"lbm_reads_lt_1ms":874,"lbm_write_time_us":41037,"lbm_writes_lt_1ms":843,"mutex_wait_us":81,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":31360,"thread_start_us":77,"threads_started":1,"update_count":4000}
I20260812 06:17:02.338804  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=18.063937
I20260812 06:17:02.386540  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.048s	user 0.031s	sys 0.015s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":20819,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:02.387045  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=2.188937
I20260812 06:17:02.403909  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: FlushDeltaMemStoresOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.404354  6442 maintenance_manager.cc:419] P 3cf9516e145d40e68b4773c0cd90b413: Scheduling MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889): perf score=1.000000
I20260812 06:17:02.420476  5823 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.649s	user 1.716s	sys 0.121s
I20260812 06:17:02.472481  5823 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.001s	sys 0.000s
I20260812 06:17:02.472960  5823 tablet_server.cc:179] TabletServer@127.5.175.193:0 shutting down...
I20260812 06:17:02.547619  6324 maintenance_manager.cc:643] P 3cf9516e145d40e68b4773c0cd90b413: MajorDeltaCompactionOp(16f82fe4afc94c9e9884fdd943d1f889) complete. Timing: real 0.143s	user 0.100s	sys 0.043s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":9515,"lbm_reads_lt_1ms":664,"lbm_write_time_us":27174,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":39808,"update_count":3000}
I20260812 06:17:02.548226  5823 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:02.548532  5823 tablet_replica.cc:333] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413: stopping tablet replica
I20260812 06:17:02.548663  5823 raft_consensus.cc:2243] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:02.548822  5823 raft_consensus.cc:2272] T 16f82fe4afc94c9e9884fdd943d1f889 P 3cf9516e145d40e68b4773c0cd90b413 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:02.553426  5823 tablet_server.cc:196] TabletServer@127.5.175.193:0 shutdown complete.
I20260812 06:17:02.600318  5823 master.cc:562] Master@127.5.175.254:37433 shutting down...
I20260812 06:17:02.603018  5823 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:02.603199  5823 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:02.603271  5823 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0b5ca15b163d42128825be7d3e326681: stopping tablet replica
I20260812 06:17:02.615443  5823 master.cc:584] Master@127.5.175.254:37433 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5088 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10211 ms total)

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