[==========] 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:20:16.131475  8980 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.197.62:45057
I20260812 06:20:16.132575  8980 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:20:16.133285  8980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.141033  8987 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:20:16.141049  8991 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:20:16.141356  8989 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:20:16.141644  8980 server_base.cc:1061] running on GCE node
I20260812 06:20:16.142236  8980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.142342  8980 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:20:16.142374  8980 hybrid_clock.cc:648] HybridClock initialized: now 1786515616142373 us; error 0 us; skew 500 ppm
I20260812 06:20:16.144536  8980 webserver.cc:533] Webserver started at http://127.8.197.62:42053/ using document root <none> and password file <none>
I20260812 06:20:16.145129  8980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.145203  8980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.145419  8980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.147610  8980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/master-0-root/instance:
uuid: "a8f14e09d454461e85380db1fd2af509"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-2w3w"
I20260812 06:20:16.151671  8980 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:20:16.154120  8997 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:20:16.155861  8980 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:16.156034  8980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/master-0-root
uuid: "a8f14e09d454461e85380db1fd2af509"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-2w3w"
I20260812 06:20:16.156169  8980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-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:20:16.174903  8980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.175679  8980 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:20:16.176074  8980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.184911  8980 rpc_server.cc:307] RPC server started. Bound to: 127.8.197.62:45057
I20260812 06:20:16.184978  9057 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.197.62:45057 every 8 connection(s)
I20260812 06:20:16.187271  9058 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:20:16.193235  9058 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509: Bootstrap starting.
I20260812 06:20:16.195827  9058 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.196889  9058 log.cc:826] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:16.199026  9058 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509: No bootstrap required, opened a new log
I20260812 06:20:16.202447  9058 raft_consensus.cc:359] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8f14e09d454461e85380db1fd2af509" member_type: VOTER }
I20260812 06:20:16.202658  9058 raft_consensus.cc:385] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.202759  9058 raft_consensus.cc:740] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a8f14e09d454461e85380db1fd2af509, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.203483  9058 consensus_queue.cc:260] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [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: "a8f14e09d454461e85380db1fd2af509" member_type: VOTER }
I20260812 06:20:16.203682  9058 raft_consensus.cc:399] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.203778  9058 raft_consensus.cc:493] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.203920  9058 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.204864  9058 raft_consensus.cc:515] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8f14e09d454461e85380db1fd2af509" member_type: VOTER }
I20260812 06:20:16.205374  9058 leader_election.cc:304] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [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: a8f14e09d454461e85380db1fd2af509; no voters: 
I20260812 06:20:16.205807  9058 leader_election.cc:290] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.205962  9063 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.206297  9063 raft_consensus.cc:697] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 1 LEADER]: Becoming Leader. State: Replica: a8f14e09d454461e85380db1fd2af509, State: Running, Role: LEADER
I20260812 06:20:16.206836  9063 consensus_queue.cc:237] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [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: "a8f14e09d454461e85380db1fd2af509" member_type: VOTER }
I20260812 06:20:16.207232  9058 sys_catalog.cc:565] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:16.208990  9064 sys_catalog.cc:455] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a8f14e09d454461e85380db1fd2af509" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8f14e09d454461e85380db1fd2af509" member_type: VOTER } }
I20260812 06:20:16.208972  9066 sys_catalog.cc:455] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a8f14e09d454461e85380db1fd2af509. Latest consensus state: current_term: 1 leader_uuid: "a8f14e09d454461e85380db1fd2af509" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a8f14e09d454461e85380db1fd2af509" member_type: VOTER } }
I20260812 06:20:16.209146  9066 sys_catalog.cc:458] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:16.209146  9064 sys_catalog.cc:458] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:16.209582  9077 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:16.209734  8980 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:16.212455  9077 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:16.218571  9077 catalog_manager.cc:1383] Generated new cluster ID: 5ea186cd8aa94c8b8fdde3ffcc5a4873
I20260812 06:20:16.218677  9077 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:16.226413  9077 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:16.227717  9077 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:16.238140  9077 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509: Generated new TSK 0
I20260812 06:20:16.239056  9077 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:16.243232  8980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.246485  9087 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:20:16.246646  8980 server_base.cc:1061] running on GCE node
W20260812 06:20:16.246399  9084 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:20:16.246512  9085 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:20:16.247076  8980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.247149  8980 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:20:16.247177  8980 hybrid_clock.cc:648] HybridClock initialized: now 1786515616247176 us; error 0 us; skew 500 ppm
I20260812 06:20:16.248224  8980 webserver.cc:533] Webserver started at http://127.8.197.1:34937/ using document root <none> and password file <none>
I20260812 06:20:16.248416  8980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.248493  8980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.248577  8980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.249006  8980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/instance:
uuid: "339f6286333141f9879abaa93e7d5322"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-2w3w"
I20260812 06:20:16.250623  8980 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:16.251848  9092 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:20:16.252197  8980 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:16.252283  8980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root
uuid: "339f6286333141f9879abaa93e7d5322"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-2w3w"
I20260812 06:20:16.252408  8980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-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:20:16.260911  8980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.261487  8980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.262027  8980 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:16.263073  8980 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:16.263130  8980 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.263201  8980 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:16.263236  8980 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.270398  8980 rpc_server.cc:307] RPC server started. Bound to: 127.8.197.1:36275
I20260812 06:20:16.270422  9167 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.197.1:36275 every 8 connection(s)
I20260812 06:20:16.289179  9168 heartbeater.cc:344] Connected to a master server at 127.8.197.62:45057
I20260812 06:20:16.289486  9168 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:16.290021  9168 heartbeater.cc:507] Master 127.8.197.62:45057 requested a full tablet report, sending...
I20260812 06:20:16.291682  9016 ts_manager.cc:194] Registered new tserver with Master: 339f6286333141f9879abaa93e7d5322 (127.8.197.1:36275)
I20260812 06:20:16.291767  8980 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020418867s
I20260812 06:20:16.293309  9016 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50702
I20260812 06:20:16.303469  9016 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50718:
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:20:16.320374  9127 tablet_service.cc:1511] Processing CreateTablet for tablet a0ee87c4a4214d24bb056b69e9242c94 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d8268396e7634d2390cb8c0e931c5cbc]), partition=
I20260812 06:20:16.320916  9127 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a0ee87c4a4214d24bb056b69e9242c94. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:16.323644  9180 tablet_bootstrap.cc:492] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Bootstrap starting.
I20260812 06:20:16.324764  9180 tablet_bootstrap.cc:654] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.326011  9180 tablet_bootstrap.cc:492] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: No bootstrap required, opened a new log
I20260812 06:20:16.326148  9180 ts_tablet_manager.cc:1403] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:16.326647  9180 raft_consensus.cc:359] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "339f6286333141f9879abaa93e7d5322" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 36275 } }
I20260812 06:20:16.326783  9180 raft_consensus.cc:385] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.326833  9180 raft_consensus.cc:740] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 339f6286333141f9879abaa93e7d5322, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.327028  9180 consensus_queue.cc:260] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [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: "339f6286333141f9879abaa93e7d5322" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 36275 } }
I20260812 06:20:16.327152  9180 raft_consensus.cc:399] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.327204  9180 raft_consensus.cc:493] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.327286  9180 raft_consensus.cc:3060] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.328344  9180 raft_consensus.cc:515] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "339f6286333141f9879abaa93e7d5322" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 36275 } }
I20260812 06:20:16.328464  9180 leader_election.cc:304] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [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: 339f6286333141f9879abaa93e7d5322; no voters: 
I20260812 06:20:16.328692  9180 leader_election.cc:290] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.328799  9182 raft_consensus.cc:2804] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.329033  9182 raft_consensus.cc:697] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 1 LEADER]: Becoming Leader. State: Replica: 339f6286333141f9879abaa93e7d5322, State: Running, Role: LEADER
I20260812 06:20:16.329068  9180 ts_tablet_manager.cc:1434] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:16.329247  9182 consensus_queue.cc:237] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [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: "339f6286333141f9879abaa93e7d5322" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 36275 } }
I20260812 06:20:16.329358  9168 heartbeater.cc:499] Master 127.8.197.62:45057 was elected leader, sending a full tablet report...
I20260812 06:20:16.332192  9016 catalog_manager.cc:5719] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 reported cstate change: term changed from 0 to 1, leader changed from <none> to 339f6286333141f9879abaa93e7d5322 (127.8.197.1). New cstate: current_term: 1 leader_uuid: "339f6286333141f9879abaa93e7d5322" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "339f6286333141f9879abaa93e7d5322" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 36275 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:16.406046  8980 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.020s	sys 0.008s
I20260812 06:20:16.521900  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=15.086190
I20260812 06:20:16.680785  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.158s	user 0.141s	sys 0.016s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":237,"delete_count":0,"dirs.queue_time_us":113,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":2626,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37388,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":203648,"thread_start_us":108,"threads_started":1,"update_count":1050}
I20260812 06:20:16.681838  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling LogGCOp(a0ee87c4a4214d24bb056b69e9242c94): free 8725963 bytes of WAL
I20260812 06:20:16.682168  9097 log_reader.cc:385] T a0ee87c4a4214d24bb056b69e9242c94: removed 1 log segments from log reader
I20260812 06:20:16.682250  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000001 (ops 1-6)
I20260812 06:20:16.684350  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: LogGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:16.684700  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94): 12308961 bytes on disk
I20260812 06:20:16.685284  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.685688  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:16.703650  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.018s	user 0.002s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5865,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.704185  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:16.838361  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.134s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1126,"lbm_read_time_us":9832,"lbm_reads_lt_1ms":364,"lbm_write_time_us":23524,"lbm_writes_lt_1ms":343,"mutex_wait_us":184,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":348,"threads_started":5,"update_count":1500}
I20260812 06:20:16.839002  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=10.126437
I20260812 06:20:16.886241  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.047s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21919,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.886778  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:16.903344  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.903937  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:17.050751  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.147s	user 0.096s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":11387,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27808,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:17.051386  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=10.126437
I20260812 06:20:17.111177  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.060s	user 0.033s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16697,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.111760  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:17.123100  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.123663  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:17.276999  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.153s	user 0.101s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":12342,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24661,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.277761  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=10.126437
I20260812 06:20:17.324887  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.047s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17702,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.325371  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:17.338248  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.338800  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:17.480589  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.142s	user 0.095s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":10930,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28878,"lbm_writes_lt_1ms":443,"mutex_wait_us":380,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:20:17.481256  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=10.126437
I20260812 06:20:17.533316  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.052s	user 0.023s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20743,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.533973  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:17.553606  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.554370  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:17.691196  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.137s	user 0.086s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1009,"lbm_read_time_us":9949,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27104,"lbm_writes_lt_1ms":443,"mutex_wait_us":391,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:20:17.691890  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=7.149875
I20260812 06:20:17.717636  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.026s	user 0.014s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10888,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:17.718324  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:17.739362  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.021s	user 0.014s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6869,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.739986  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:17.880481  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.140s	user 0.068s	sys 0.064s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":830,"lbm_read_time_us":11263,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20314,"lbm_writes_lt_1ms":343,"mutex_wait_us":350,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":1500}
I20260812 06:20:17.881186  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=10.126437
I20260812 06:20:17.933305  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.052s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19081,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.934015  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:17.950241  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.950904  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:18.089381  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.138s	user 0.113s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":593,"lbm_read_time_us":9905,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25963,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:20:18.090230  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=10.126437
I20260812 06:20:18.136536  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.046s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18454,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.137058  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:18.148138  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.148782  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:18.178215  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":299,"dirs.run_wall_time_us":1751,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1877,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:18.179081  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling LogGCOp(a0ee87c4a4214d24bb056b69e9242c94): free 127961101 bytes of WAL
I20260812 06:20:18.179322  9097 log_reader.cc:385] T a0ee87c4a4214d24bb056b69e9242c94: removed 12 log segments from log reader
I20260812 06:20:18.179373  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000002 (ops 7-11)
I20260812 06:20:18.179402  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000003 (ops 12-16)
I20260812 06:20:18.179471  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000004 (ops 17-21)
I20260812 06:20:18.179512  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000005 (ops 22-26)
I20260812 06:20:18.179548  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000006 (ops 27-31)
I20260812 06:20:18.179587  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000007 (ops 32-36)
I20260812 06:20:18.179625  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000008 (ops 37-41)
I20260812 06:20:18.179664  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000009 (ops 42-46)
I20260812 06:20:18.179704  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000010 (ops 47-51)
I20260812 06:20:18.179742  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000011 (ops 52-56)
I20260812 06:20:18.179780  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000012 (ops 57-61)
I20260812 06:20:18.179817  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000013 (ops 62-66)
I20260812 06:20:18.211928  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: LogGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.033s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:20:18.212924  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94): 472 bytes on disk
I20260812 06:20:18.213498  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.214097  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=4.173312
I20260812 06:20:18.229640  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":5661584,"delete_count":0,"lbm_write_time_us":6640,"lbm_writes_lt_1ms":141,"reinsert_count":0,"update_count":690}
I20260812 06:20:18.230145  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.196750
I20260812 06:20:18.240698  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3631,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:20:18.241199  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:18.430617  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.189s	user 0.140s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836338,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":687,"lbm_read_time_us":14671,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37802,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:20:18.431603  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:18.485124  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.053s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23788,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.485641  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:18.498178  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.498737  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:18.664526  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.166s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":327,"lbm_read_time_us":11024,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30280,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:18.665405  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:18.720930  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.055s	user 0.045s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25662,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.721525  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:18.873297  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.152s	user 0.098s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":338,"lbm_read_time_us":9888,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26578,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:20:18.874294  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=11.118625
I20260812 06:20:18.918006  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.043s	user 0.037s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19251,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.918497  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:18.948529  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.030s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6320,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.949028  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:18.960881  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.961849  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:19.157579  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.195s	user 0.146s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":565,"lbm_read_time_us":13100,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30457,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":49280,"update_count":2500}
I20260812 06:20:19.158388  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:19.217438  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.059s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.217955  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:19.229313  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.230080  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:19.400888  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.171s	user 0.101s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":11425,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33790,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:19.401775  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=11.118625
I20260812 06:20:19.437048  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.035s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14799,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.437582  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:19.464646  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5202,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.465143  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:19.476694  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.477396  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:19.645577  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.168s	user 0.136s	sys 0.019s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":190,"lbm_read_time_us":12610,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31430,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:19.646675  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:19.701256  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.054s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19847,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.701823  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:19.713835  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.714363  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:19.748385  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1542,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1806,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:19.749153  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling LogGCOp(a0ee87c4a4214d24bb056b69e9242c94): free 133024379 bytes of WAL
I20260812 06:20:19.749387  9097 log_reader.cc:385] T a0ee87c4a4214d24bb056b69e9242c94: removed 13 log segments from log reader
I20260812 06:20:19.749451  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000014 (ops 67-71)
I20260812 06:20:19.749529  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000015 (ops 72-76)
I20260812 06:20:19.749591  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000016 (ops 77-81)
I20260812 06:20:19.749630  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000017 (ops 82-86)
I20260812 06:20:19.749668  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000018 (ops 87-91)
I20260812 06:20:19.749706  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000019 (ops 92-96)
I20260812 06:20:19.749743  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000020 (ops 97-101)
I20260812 06:20:19.749780  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000021 (ops 102-106)
I20260812 06:20:19.749818  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000022 (ops 107-111)
I20260812 06:20:19.749855  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000023 (ops 112-116)
I20260812 06:20:19.749892  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000024 (ops 117-120)
I20260812 06:20:19.749929  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000025 (ops 121-125)
I20260812 06:20:19.749965  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000026 (ops 126-130)
I20260812 06:20:19.783197  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: LogGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.034s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:20:19.783684  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94): 483 bytes on disk
I20260812 06:20:19.784139  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.784677  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=6.157687
I20260812 06:20:19.819082  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.034s	user 0.025s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10857,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:19.819597  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:20.046446  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.227s	user 0.146s	sys 0.081s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938667,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":514,"lbm_read_time_us":16594,"lbm_reads_lt_1ms":765,"lbm_write_time_us":42274,"lbm_writes_lt_1ms":743,"mutex_wait_us":66,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:20:20.047386  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=18.063937
I20260812 06:20:20.120217  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.073s	user 0.046s	sys 0.013s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26657,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:20.120790  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:20.132846  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.133885  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:20.374900  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.241s	user 0.125s	sys 0.108s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":836,"lbm_read_time_us":15090,"lbm_reads_lt_1ms":672,"lbm_write_time_us":40586,"lbm_writes_lt_1ms":643,"mutex_wait_us":415,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":49280,"update_count":3000}
I20260812 06:20:20.375538  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=16.079562
I20260812 06:20:20.437079  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.061s	user 0.032s	sys 0.023s Metrics: {"bytes_written":18009850,"delete_count":0,"lbm_write_time_us":26547,"lbm_writes_lt_1ms":442,"reinsert_count":0,"update_count":2195}
I20260812 06:20:20.437745  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.196750
I20260812 06:20:20.448259  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2912935,"delete_count":0,"lbm_write_time_us":3085,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:20:20.448730  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:20.460422  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4742,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.460965  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:20.669950  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.209s	user 0.108s	sys 0.094s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836225,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1172,"lbm_read_time_us":16667,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35881,"lbm_writes_lt_1ms":643,"mutex_wait_us":66,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":3000}
I20260812 06:20:20.670744  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:20.718793  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.048s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20767,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.719549  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:20.886277  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.167s	user 0.098s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1064,"lbm_read_time_us":12503,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25402,"lbm_writes_lt_1ms":443,"mutex_wait_us":432,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:20.887008  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:20.942420  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.055s	user 0.038s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23066,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.942935  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:20.955259  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.955777  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:21.152631  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.196s	user 0.127s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":975,"lbm_read_time_us":12976,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30687,"lbm_writes_lt_1ms":543,"mutex_wait_us":329,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2500}
I20260812 06:20:21.153456  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=14.095187
I20260812 06:20:21.203725  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.050s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20837,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.204244  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:21.217434  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.218127  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:21.252871  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushMRSOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.035s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":296,"dirs.run_wall_time_us":1511,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1690,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:21.253679  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling LogGCOp(a0ee87c4a4214d24bb056b69e9242c94): free 112239561 bytes of WAL
I20260812 06:20:21.253904  9097 log_reader.cc:385] T a0ee87c4a4214d24bb056b69e9242c94: removed 11 log segments from log reader
I20260812 06:20:21.253948  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000027 (ops 131-135)
I20260812 06:20:21.253976  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000028 (ops 136-140)
I20260812 06:20:21.254042  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000029 (ops 141-145)
I20260812 06:20:21.254102  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000030 (ops 146-150)
I20260812 06:20:21.254144  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000031 (ops 151-155)
I20260812 06:20:21.254185  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000032 (ops 156-160)
I20260812 06:20:21.254225  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000033 (ops 161-165)
I20260812 06:20:21.254274  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000034 (ops 166-170)
I20260812 06:20:21.254313  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000035 (ops 171-174)
I20260812 06:20:21.254352  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000036 (ops 175-179)
I20260812 06:20:21.254393  9097 log.cc:1079] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/a0ee87c4a4214d24bb056b69e9242c94/wal-000000037 (ops 180-184)
I20260812 06:20:21.285037  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: LogGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:21.286706  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94): 446 bytes on disk
I20260812 06:20:21.287221  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: UndoDeltaBlockGCOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:20:21.287850  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=3.181125
I20260812 06:20:21.302706  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5227,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:21.303256  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=2.188937
I20260812 06:20:21.313601  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.314136  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:21.562047  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.248s	user 0.182s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938772,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1510,"lbm_read_time_us":17798,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42956,"lbm_writes_lt_1ms":743,"mutex_wait_us":1059,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:20:21.562877  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=16.079562
I20260812 06:20:21.614472  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.051s	user 0.035s	sys 0.013s Metrics: {"bytes_written":17968826,"delete_count":0,"lbm_write_time_us":23892,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:20:21.615110  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.196750
I20260812 06:20:21.629688  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: FlushDeltaMemStoresOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.014s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3645,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:20:21.630364  9169 maintenance_manager.cc:419] P 339f6286333141f9879abaa93e7d5322: Scheduling MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94): perf score=1.000000
I20260812 06:20:21.640846  8980 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.235s	user 1.894s	sys 0.144s
I20260812 06:20:21.719350  8980 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.000s	sys 0.004s
I20260812 06:20:21.720052  8980 tablet_server.cc:179] TabletServer@127.8.197.1:0 shutting down...
I20260812 06:20:21.784353  9097 maintenance_manager.cc:643] P 339f6286333141f9879abaa93e7d5322: MajorDeltaCompactionOp(a0ee87c4a4214d24bb056b69e9242c94) complete. Timing: real 0.154s	user 0.094s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733693,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1259,"lbm_read_time_us":13517,"lbm_reads_lt_1ms":560,"lbm_write_time_us":27238,"lbm_writes_lt_1ms":543,"mutex_wait_us":361,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":213376,"update_count":2500}
I20260812 06:20:21.785050  8980 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:21.785470  8980 tablet_replica.cc:333] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322: stopping tablet replica
I20260812 06:20:21.785723  8980 raft_consensus.cc:2243] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.785974  8980 raft_consensus.cc:2272] T a0ee87c4a4214d24bb056b69e9242c94 P 339f6286333141f9879abaa93e7d5322 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.803324  8980 tablet_server.cc:196] TabletServer@127.8.197.1:0 shutdown complete.
I20260812 06:20:21.831910  8980 master.cc:562] Master@127.8.197.62:45057 shutting down...
I20260812 06:20:21.836129  8980 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.836349  8980 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.836436  8980 tablet_replica.cc:333] T 00000000000000000000000000000000 P a8f14e09d454461e85380db1fd2af509: stopping tablet replica
I20260812 06:20:21.849179  8980 master.cc:584] Master@127.8.197.62:45057 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5821 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:21.967214  8980 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.197.62:34825
I20260812 06:20:21.967748  8980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.971138  9206 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:20:21.971293  8980 server_base.cc:1061] running on GCE node
W20260812 06:20:21.971374  9204 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:20:21.971199  9202 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:20:21.971689  8980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.971766  8980 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:20:21.971793  8980 hybrid_clock.cc:648] HybridClock initialized: now 1786515621971793 us; error 0 us; skew 500 ppm
I20260812 06:20:21.972697  8980 webserver.cc:533] Webserver started at http://127.8.197.62:32911/ using document root <none> and password file <none>
I20260812 06:20:21.972888  8980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.973011  8980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.973218  8980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.973683  8980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/master-0-root/instance:
uuid: "c3cef80e7f0c40709adb397f9589047b"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-2w3w"
I20260812 06:20:21.975476  8980 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.976600  9211 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:20:21.977424  8980 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:21.977669  8980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/master-0-root
uuid: "c3cef80e7f0c40709adb397f9589047b"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-2w3w"
I20260812 06:20:21.977795  8980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-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:20:21.999513  8980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.000047  8980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.005393  8980 rpc_server.cc:307] RPC server started. Bound to: 127.8.197.62:34825
I20260812 06:20:22.006546  9272 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.197.62:34825 every 8 connection(s)
I20260812 06:20:22.012121  9273 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:20:22.014549  9273 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b: Bootstrap starting.
I20260812 06:20:22.015548  9273 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.016860  9273 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b: No bootstrap required, opened a new log
I20260812 06:20:22.017352  9273 raft_consensus.cc:359] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cef80e7f0c40709adb397f9589047b" member_type: VOTER }
I20260812 06:20:22.017478  9273 raft_consensus.cc:385] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.017524  9273 raft_consensus.cc:740] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c3cef80e7f0c40709adb397f9589047b, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.017705  9273 consensus_queue.cc:260] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [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: "c3cef80e7f0c40709adb397f9589047b" member_type: VOTER }
I20260812 06:20:22.017804  9273 raft_consensus.cc:399] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.017861  9273 raft_consensus.cc:493] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.017920  9273 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.018715  9273 raft_consensus.cc:515] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cef80e7f0c40709adb397f9589047b" member_type: VOTER }
I20260812 06:20:22.018887  9273 leader_election.cc:304] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [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: c3cef80e7f0c40709adb397f9589047b; no voters: 
I20260812 06:20:22.019145  9273 leader_election.cc:290] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.019286  9276 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.019558  9276 raft_consensus.cc:697] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 1 LEADER]: Becoming Leader. State: Replica: c3cef80e7f0c40709adb397f9589047b, State: Running, Role: LEADER
I20260812 06:20:22.019703  9273 sys_catalog.cc:565] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:22.019743  9276 consensus_queue.cc:237] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [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: "c3cef80e7f0c40709adb397f9589047b" member_type: VOTER }
I20260812 06:20:22.020342  9277 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c3cef80e7f0c40709adb397f9589047b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cef80e7f0c40709adb397f9589047b" member_type: VOTER } }
I20260812 06:20:22.020393  9278 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [sys.catalog]: SysCatalogTable state changed. Reason: New leader c3cef80e7f0c40709adb397f9589047b. Latest consensus state: current_term: 1 leader_uuid: "c3cef80e7f0c40709adb397f9589047b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3cef80e7f0c40709adb397f9589047b" member_type: VOTER } }
I20260812 06:20:22.020530  9277 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.020552  9278 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.021106  9281 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:22.022261  9281 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:22.022516  8980 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:22.024444  9281 catalog_manager.cc:1383] Generated new cluster ID: 4fdd0af3dd004596a2719e4762a20517
I20260812 06:20:22.024515  9281 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:22.032475  9281 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:22.033109  9281 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:22.046103  9281 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b: Generated new TSK 0
I20260812 06:20:22.046343  9281 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:22.055212  8980 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.057437  9299 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:20:22.057446  9302 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:20:22.057461  9300 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:20:22.057722  8980 server_base.cc:1061] running on GCE node
I20260812 06:20:22.058032  8980 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.058087  8980 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:20:22.058105  8980 hybrid_clock.cc:648] HybridClock initialized: now 1786515622058105 us; error 0 us; skew 500 ppm
I20260812 06:20:22.059010  8980 webserver.cc:533] Webserver started at http://127.8.197.1:39843/ using document root <none> and password file <none>
I20260812 06:20:22.059176  8980 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.059221  8980 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.059283  8980 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.059659  8980 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/instance:
uuid: "f52cec16a5cc4ec8882e0fa35b73091e"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-2w3w"
I20260812 06:20:22.061419  8980 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:22.062529  9308 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:20:22.062943  8980 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.063098  8980 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root
uuid: "f52cec16a5cc4ec8882e0fa35b73091e"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-2w3w"
I20260812 06:20:22.063202  8980 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-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:20:22.080549  8980 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.081041  8980 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.081398  8980 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:22.081931  8980 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:22.081992  8980 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.082050  8980 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:22.082101  8980 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.087409  8980 rpc_server.cc:307] RPC server started. Bound to: 127.8.197.1:42687
I20260812 06:20:22.087442  9379 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.197.1:42687 every 8 connection(s)
I20260812 06:20:22.101787  9380 heartbeater.cc:344] Connected to a master server at 127.8.197.62:34825
I20260812 06:20:22.101971  9380 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:22.102320  9380 heartbeater.cc:507] Master 127.8.197.62:34825 requested a full tablet report, sending...
I20260812 06:20:22.103194  9232 ts_manager.cc:194] Registered new tserver with Master: f52cec16a5cc4ec8882e0fa35b73091e (127.8.197.1:42687)
I20260812 06:20:22.103572  8980 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015689055s
I20260812 06:20:22.104295  9232 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49970
I20260812 06:20:22.111821  9232 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49982:
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:20:22.121304  9341 tablet_service.cc:1511] Processing CreateTablet for tablet 257a3d6fe2694f74bbd2255b30431862 (DEFAULT_TABLE table=heavy-update-compaction-test [id=71a7d765bc1b4f7ca9b0dae2b46a1e22]), partition=
I20260812 06:20:22.121625  9341 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 257a3d6fe2694f74bbd2255b30431862. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.123900  9392 tablet_bootstrap.cc:492] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Bootstrap starting.
I20260812 06:20:22.124806  9392 tablet_bootstrap.cc:654] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.125957  9392 tablet_bootstrap.cc:492] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: No bootstrap required, opened a new log
I20260812 06:20:22.126031  9392 ts_tablet_manager.cc:1403] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:22.126619  9392 raft_consensus.cc:359] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f52cec16a5cc4ec8882e0fa35b73091e" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 42687 } }
I20260812 06:20:22.126713  9392 raft_consensus.cc:385] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.126735  9392 raft_consensus.cc:740] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f52cec16a5cc4ec8882e0fa35b73091e, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.126888  9392 consensus_queue.cc:260] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [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: "f52cec16a5cc4ec8882e0fa35b73091e" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 42687 } }
I20260812 06:20:22.127029  9392 raft_consensus.cc:399] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.127082  9392 raft_consensus.cc:493] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.127138  9392 raft_consensus.cc:3060] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.127900  9392 raft_consensus.cc:515] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f52cec16a5cc4ec8882e0fa35b73091e" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 42687 } }
I20260812 06:20:22.128073  9392 leader_election.cc:304] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [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: f52cec16a5cc4ec8882e0fa35b73091e; no voters: 
I20260812 06:20:22.128298  9392 leader_election.cc:290] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.128482  9395 raft_consensus.cc:2804] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.128669  9392 ts_tablet_manager.cc:1434] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:22.128685  9380 heartbeater.cc:499] Master 127.8.197.62:34825 was elected leader, sending a full tablet report...
I20260812 06:20:22.128741  9395 raft_consensus.cc:697] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 1 LEADER]: Becoming Leader. State: Replica: f52cec16a5cc4ec8882e0fa35b73091e, State: Running, Role: LEADER
I20260812 06:20:22.128986  9395 consensus_queue.cc:237] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [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: "f52cec16a5cc4ec8882e0fa35b73091e" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 42687 } }
I20260812 06:20:22.130445  9232 catalog_manager.cc:5719] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e reported cstate change: term changed from 0 to 1, leader changed from <none> to f52cec16a5cc4ec8882e0fa35b73091e (127.8.197.1). New cstate: current_term: 1 leader_uuid: "f52cec16a5cc4ec8882e0fa35b73091e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f52cec16a5cc4ec8882e0fa35b73091e" member_type: VOTER last_known_addr { host: "127.8.197.1" port: 42687 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:22.193683  8980 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.008s
I20260812 06:20:22.339143  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushMRSOp(257a3d6fe2694f74bbd2255b30431862): perf score=18.062753
I20260812 06:20:22.534194  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushMRSOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.195s	user 0.120s	sys 0.064s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":920,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48553,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:22.535029  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling LogGCOp(257a3d6fe2694f74bbd2255b30431862): free 20743880 bytes of WAL
I20260812 06:20:22.535295  9313 log_reader.cc:385] T 257a3d6fe2694f74bbd2255b30431862: removed 2 log segments from log reader
I20260812 06:20:22.535339  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000001 (ops 1-6)
I20260812 06:20:22.535370  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000002 (ops 7-11)
I20260812 06:20:22.540298  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: LogGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:22.540750  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862): 16411398 bytes on disk
I20260812 06:20:22.541249  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.541699  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:22.554241  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.554867  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:22.720781  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.166s	user 0.105s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":860,"lbm_read_time_us":13062,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26716,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":338,"threads_started":5,"update_count":2000}
I20260812 06:20:22.721529  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=10.126437
I20260812 06:20:22.759096  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.037s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.759609  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:22.775501  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.776062  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:22.907178  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.131s	user 0.099s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":9899,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26172,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:20:22.907804  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=10.126437
I20260812 06:20:22.943751  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.035s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15168,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.944371  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:22.963393  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.019s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.964026  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:23.105670  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.141s	user 0.121s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":879,"lbm_read_time_us":8453,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27153,"lbm_writes_lt_1ms":443,"mutex_wait_us":555,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:20:23.106393  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=11.118625
I20260812 06:20:23.138290  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13938,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:23.139142  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:23.153179  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5232,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.153643  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:23.299587  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.146s	user 0.114s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1311,"lbm_read_time_us":10907,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28373,"lbm_writes_lt_1ms":443,"mutex_wait_us":360,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:20:23.300345  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=10.126437
I20260812 06:20:23.351676  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.051s	user 0.028s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16107,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.352288  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:23.369354  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.369949  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:23.527664  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.158s	user 0.122s	sys 0.035s 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":223,"lbm_read_time_us":13524,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23710,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.528239  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=10.126437
I20260812 06:20:23.568660  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.040s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16863,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.569209  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:23.582006  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.582617  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:23.723145  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.140s	user 0.102s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1002,"lbm_read_time_us":9746,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28215,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:23.724028  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=10.126437
I20260812 06:20:23.763243  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.039s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15159,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.763736  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:23.781277  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.017s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.781916  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushMRSOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:23.816394  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushMRSOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1644,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2182,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:23.817023  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling LogGCOp(257a3d6fe2694f74bbd2255b30431862): free 108535449 bytes of WAL
I20260812 06:20:23.817260  9313 log_reader.cc:385] T 257a3d6fe2694f74bbd2255b30431862: removed 11 log segments from log reader
I20260812 06:20:23.817322  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000003 (ops 12-16)
I20260812 06:20:23.817373  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000004 (ops 17-21)
I20260812 06:20:23.817432  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000005 (ops 22-26)
I20260812 06:20:23.817476  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000006 (ops 27-31)
I20260812 06:20:23.817515  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000007 (ops 32-36)
I20260812 06:20:23.817554  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000008 (ops 37-40)
I20260812 06:20:23.817593  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000009 (ops 41-45)
I20260812 06:20:23.817631  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000010 (ops 46-50)
I20260812 06:20:23.817670  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000011 (ops 51-54)
I20260812 06:20:23.817709  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000012 (ops 55-59)
I20260812 06:20:23.817747  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000013 (ops 60-64)
I20260812 06:20:23.842939  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: LogGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:23.843429  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=3.181125
I20260812 06:20:23.855937  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4982,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:23.856401  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:23.867555  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.868101  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862): 448 bytes on disk
I20260812 06:20:23.868698  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.869431  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:24.043707  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.174s	user 0.147s	sys 0.027s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":177,"lbm_read_time_us":13405,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32993,"lbm_writes_lt_1ms":643,"mutex_wait_us":70,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:20:24.044457  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:24.099864  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.055s	user 0.047s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.100497  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:24.117887  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.118386  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:24.290472  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.172s	user 0.118s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":12044,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31760,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:20:24.291378  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:24.368096  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.077s	user 0.023s	sys 0.036s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":30564,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.368683  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:24.380789  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4504,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.381630  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:24.578241  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.196s	user 0.125s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1078,"lbm_read_time_us":14572,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32889,"lbm_writes_lt_1ms":543,"mutex_wait_us":11,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26752,"update_count":2500}
I20260812 06:20:24.578872  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:24.647028  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.068s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.647606  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:24.659554  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.660204  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:24.849197  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.189s	user 0.130s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":13508,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33950,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:20:24.849823  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:24.918843  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.069s	user 0.012s	sys 0.048s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.919561  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:24.930907  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.931466  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:25.131299  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.200s	user 0.130s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":13694,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32332,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:25.132059  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:25.191949  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.060s	user 0.035s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27459,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.192613  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:25.213986  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.021s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.214597  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:25.415311  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.200s	user 0.128s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":961,"lbm_read_time_us":12743,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33421,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:20:25.416038  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:25.471113  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.055s	user 0.037s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25822,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.471628  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:25.483501  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.483975  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushMRSOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:25.528504  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushMRSOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.044s	user 0.041s	sys 0.002s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1562,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2102,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:25.529307  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling LogGCOp(257a3d6fe2694f74bbd2255b30431862): free 136728177 bytes of WAL
I20260812 06:20:25.529594  9313 log_reader.cc:385] T 257a3d6fe2694f74bbd2255b30431862: removed 13 log segments from log reader
I20260812 06:20:25.529654  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000014 (ops 65-69)
I20260812 06:20:25.529695  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000015 (ops 70-74)
I20260812 06:20:25.529726  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000016 (ops 75-79)
I20260812 06:20:25.529758  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000017 (ops 80-84)
I20260812 06:20:25.529788  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000018 (ops 85-89)
I20260812 06:20:25.529814  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000019 (ops 90-94)
I20260812 06:20:25.529856  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000020 (ops 95-99)
I20260812 06:20:25.529892  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000021 (ops 100-104)
I20260812 06:20:25.529915  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000022 (ops 105-109)
I20260812 06:20:25.529942  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000023 (ops 110-114)
I20260812 06:20:25.529964  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000024 (ops 115-119)
I20260812 06:20:25.529994  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000025 (ops 120-124)
I20260812 06:20:25.530023  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000026 (ops 125-129)
I20260812 06:20:25.566840  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: LogGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.037s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:20:25.567353  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=3.181125
I20260812 06:20:25.592000  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.024s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7433,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.592511  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:25.602932  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.603500  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862): 491 bytes on disk
I20260812 06:20:25.603984  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.604847  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:25.858443  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.253s	user 0.173s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":219,"lbm_read_time_us":18544,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38823,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:20:25.859437  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=18.063937
I20260812 06:20:25.930176  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.071s	user 0.034s	sys 0.018s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26055,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:25.930697  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:25.942406  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.943224  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:26.173043  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.230s	user 0.133s	sys 0.096s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":16154,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37662,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":3000}
I20260812 06:20:26.173800  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:26.228652  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.055s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.229269  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:26.246251  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.246789  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:26.432298  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.185s	user 0.130s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":14596,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30875,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:20:26.432914  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:26.494552  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.061s	user 0.009s	sys 0.047s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23995,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.495205  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:26.507875  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.508543  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:26.696164  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.187s	user 0.129s	sys 0.057s 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":484,"lbm_read_time_us":13968,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31728,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.696941  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=11.118625
I20260812 06:20:26.736399  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.039s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16560,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:26.737093  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:26.754712  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6865,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.755352  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:26.917765  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.162s	user 0.098s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":488,"dirs.run_cpu_time_us":632,"dirs.run_wall_time_us":3184,"lbm_read_time_us":10775,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24835,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:20:26.918551  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=14.095187
I20260812 06:20:26.966303  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.048s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21404,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.966861  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:26.979359  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.012s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.979972  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:27.148068  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.168s	user 0.141s	sys 0.021s 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":499,"lbm_read_time_us":12067,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32306,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:20:27.148835  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=11.118625
I20260812 06:20:27.186342  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.037s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16087,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:27.187022  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:27.213853  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.027s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6305,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.214440  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=2.188937
I20260812 06:20:27.225651  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.226351  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushMRSOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:27.257877  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushMRSOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.031s	user 0.020s	sys 0.008s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1647,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1862,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:27.258563  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling LogGCOp(257a3d6fe2694f74bbd2255b30431862): free 132571642 bytes of WAL
I20260812 06:20:27.258797  9313 log_reader.cc:385] T 257a3d6fe2694f74bbd2255b30431862: removed 13 log segments from log reader
I20260812 06:20:27.258839  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000027 (ops 130-134)
I20260812 06:20:27.258868  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000028 (ops 135-138)
I20260812 06:20:27.258925  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000029 (ops 139-143)
I20260812 06:20:27.258991  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000030 (ops 144-148)
I20260812 06:20:27.259032  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000031 (ops 149-153)
I20260812 06:20:27.259092  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000032 (ops 154-158)
I20260812 06:20:27.259140  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000033 (ops 159-163)
I20260812 06:20:27.259176  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000034 (ops 164-168)
I20260812 06:20:27.259212  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000035 (ops 169-172)
I20260812 06:20:27.259259  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000036 (ops 173-177)
I20260812 06:20:27.259297  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000037 (ops 178-182)
I20260812 06:20:27.259335  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000038 (ops 183-187)
I20260812 06:20:27.259373  9313 log.cc:1079] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: Deleting log segment in path: /tmp/dist-test-task3jc8BW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515616119979-8980-0/minicluster-data/ts-0-root/wals/257a3d6fe2694f74bbd2255b30431862/wal-000000039 (ops 188-192)
I20260812 06:20:27.293272  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: LogGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.035s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:20:27.293823  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862): 493 bytes on disk
I20260812 06:20:27.294432  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: UndoDeltaBlockGCOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.295248  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=3.181125
I20260812 06:20:27.313915  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.018s	user 0.008s	sys 0.009s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":7895,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:20:27.314469  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.196750
I20260812 06:20:27.338502  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: FlushDeltaMemStoresOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.024s	user 0.009s	sys 0.009s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:20:27.339144  9381 maintenance_manager.cc:419] P f52cec16a5cc4ec8882e0fa35b73091e: Scheduling MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862): perf score=1.000000
I20260812 06:20:27.447962  8980 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.254s	user 1.943s	sys 0.171s
I20260812 06:20:27.557803  8980 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.109s	user 0.001s	sys 0.000s
I20260812 06:20:27.558393  8980 tablet_server.cc:179] TabletServer@127.8.197.1:0 shutting down...
I20260812 06:20:27.581140  9313 maintenance_manager.cc:643] P f52cec16a5cc4ec8882e0fa35b73091e: MajorDeltaCompactionOp(257a3d6fe2694f74bbd2255b30431862) complete. Timing: real 0.242s	user 0.181s	sys 0.061s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979836,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":242,"lbm_read_time_us":16880,"lbm_reads_lt_1ms":771,"lbm_write_time_us":39665,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":30080,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:20:27.582574  8980 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:27.583253  8980 tablet_replica.cc:333] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e: stopping tablet replica
I20260812 06:20:27.583428  8980 raft_consensus.cc:2243] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.583668  8980 raft_consensus.cc:2272] T 257a3d6fe2694f74bbd2255b30431862 P f52cec16a5cc4ec8882e0fa35b73091e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.600956  8980 tablet_server.cc:196] TabletServer@127.8.197.1:0 shutdown complete.
I20260812 06:20:27.641973  8980 master.cc:562] Master@127.8.197.62:34825 shutting down...
I20260812 06:20:27.645921  8980 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.646119  8980 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.646169  8980 tablet_replica.cc:333] T 00000000000000000000000000000000 P c3cef80e7f0c40709adb397f9589047b: stopping tablet replica
I20260812 06:20:27.658694  8980 master.cc:584] Master@127.8.197.62:34825 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5801 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11623 ms total)

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