[==========] 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:19:59.415531 22194 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.172.190:34203
I20260812 06:19:59.416743 22194 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:19:59.417395 22194 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:59.424496 22194 server_base.cc:1061] running on GCE node
W20260812 06:19:59.424609 22199 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:19:59.424513 22200 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:19:59.424798 22204 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:19:59.425323 22194 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.425443 22194 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:19:59.425495 22194 hybrid_clock.cc:648] HybridClock initialized: now 1786515599425493 us; error 0 us; skew 500 ppm
I20260812 06:19:59.427366 22194 webserver.cc:533] Webserver started at http://127.21.172.190:32901/ using document root <none> and password file <none>
I20260812 06:19:59.427919 22194 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.428004 22194 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.428273 22194 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.429981 22194 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/master-0-root/instance:
uuid: "be2dbe4d095e4a279bff6e2522dcc11c"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-3h5h"
I20260812 06:19:59.433497 22194 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:19:59.435547 22213 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:19:59.436532 22194 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:59.436672 22194 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/master-0-root
uuid: "be2dbe4d095e4a279bff6e2522dcc11c"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-3h5h"
I20260812 06:19:59.436770 22194 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-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:19:59.472580 22194 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.473408 22194 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:19:59.473618 22194 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.482342 22194 rpc_server.cc:307] RPC server started. Bound to: 127.21.172.190:34203
I20260812 06:19:59.482352 22313 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.172.190:34203 every 8 connection(s)
I20260812 06:19:59.484795 22314 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:19:59.490338 22314 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c: Bootstrap starting.
I20260812 06:19:59.492660 22314 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.493614 22314 log.cc:826] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:59.495297 22314 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c: No bootstrap required, opened a new log
I20260812 06:19:59.498219 22314 raft_consensus.cc:359] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be2dbe4d095e4a279bff6e2522dcc11c" member_type: VOTER }
I20260812 06:19:59.498386 22314 raft_consensus.cc:385] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.498426 22314 raft_consensus.cc:740] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: be2dbe4d095e4a279bff6e2522dcc11c, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.499046 22314 consensus_queue.cc:260] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [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: "be2dbe4d095e4a279bff6e2522dcc11c" member_type: VOTER }
I20260812 06:19:59.499186 22314 raft_consensus.cc:399] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.499233 22314 raft_consensus.cc:493] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.499317 22314 raft_consensus.cc:3060] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.500061 22314 raft_consensus.cc:515] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be2dbe4d095e4a279bff6e2522dcc11c" member_type: VOTER }
I20260812 06:19:59.500438 22314 leader_election.cc:304] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [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: be2dbe4d095e4a279bff6e2522dcc11c; no voters: 
I20260812 06:19:59.500705 22314 leader_election.cc:290] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.500905 22324 raft_consensus.cc:2804] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.501194 22324 raft_consensus.cc:697] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 1 LEADER]: Becoming Leader. State: Replica: be2dbe4d095e4a279bff6e2522dcc11c, State: Running, Role: LEADER
I20260812 06:19:59.501600 22324 consensus_queue.cc:237] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [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: "be2dbe4d095e4a279bff6e2522dcc11c" member_type: VOTER }
I20260812 06:19:59.501837 22314 sys_catalog.cc:565] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:59.503620 22330 sys_catalog.cc:455] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [sys.catalog]: SysCatalogTable state changed. Reason: New leader be2dbe4d095e4a279bff6e2522dcc11c. Latest consensus state: current_term: 1 leader_uuid: "be2dbe4d095e4a279bff6e2522dcc11c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be2dbe4d095e4a279bff6e2522dcc11c" member_type: VOTER } }
I20260812 06:19:59.503937 22330 sys_catalog.cc:458] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.503654 22328 sys_catalog.cc:455] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "be2dbe4d095e4a279bff6e2522dcc11c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be2dbe4d095e4a279bff6e2522dcc11c" member_type: VOTER } }
I20260812 06:19:59.504246 22328 sys_catalog.cc:458] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.504273 22348 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:59.504452 22194 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:59.506584 22348 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:59.511197 22348 catalog_manager.cc:1383] Generated new cluster ID: c859b0e00b9044b89514ed983d6d3afe
I20260812 06:19:59.511268 22348 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:59.528304 22348 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:59.529317 22348 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:59.539350 22348 catalog_manager.cc:6092] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c: Generated new TSK 0
I20260812 06:19:59.540083 22348 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:59.569867 22194 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:59.573093 22362 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:19:59.573186 22367 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:19:59.573190 22363 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:19:59.573338 22194 server_base.cc:1061] running on GCE node
I20260812 06:19:59.573594 22194 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.573652 22194 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:19:59.573680 22194 hybrid_clock.cc:648] HybridClock initialized: now 1786515599573680 us; error 0 us; skew 500 ppm
I20260812 06:19:59.574720 22194 webserver.cc:533] Webserver started at http://127.21.172.129:40195/ using document root <none> and password file <none>
I20260812 06:19:59.574892 22194 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.574949 22194 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.575028 22194 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.575470 22194 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/instance:
uuid: "02140ef1ef26479882e029c78fac837f"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-3h5h"
I20260812 06:19:59.577363 22194 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:59.578462 22375 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:19:59.578748 22194 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.578812 22194 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root
uuid: "02140ef1ef26479882e029c78fac837f"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-3h5h"
I20260812 06:19:59.578904 22194 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-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:19:59.589774 22194 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.590288 22194 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.590817 22194 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:59.591667 22194 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:59.591717 22194 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.591784 22194 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:59.591827 22194 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.599716 22194 rpc_server.cc:307] RPC server started. Bound to: 127.21.172.129:36271
I20260812 06:19:59.599745 22490 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.172.129:36271 every 8 connection(s)
I20260812 06:19:59.610601 22491 heartbeater.cc:344] Connected to a master server at 127.21.172.190:34203
I20260812 06:19:59.610878 22491 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:59.611339 22491 heartbeater.cc:507] Master 127.21.172.190:34203 requested a full tablet report, sending...
I20260812 06:19:59.612776 22252 ts_manager.cc:194] Registered new tserver with Master: 02140ef1ef26479882e029c78fac837f (127.21.172.129:36271)
I20260812 06:19:59.612870 22194 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012477863s
I20260812 06:19:59.614015 22252 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35376
I20260812 06:19:59.622627 22252 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35392:
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:19:59.636909 22414 tablet_service.cc:1511] Processing CreateTablet for tablet d6e40e322bb741658d25ab48a4b29214 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e3fc944d33084322a9a619342860256c]), partition=
I20260812 06:19:59.637422 22414 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d6e40e322bb741658d25ab48a4b29214. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:59.640434 22507 tablet_bootstrap.cc:492] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Bootstrap starting.
I20260812 06:19:59.642030 22507 tablet_bootstrap.cc:654] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.643411 22507 tablet_bootstrap.cc:492] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: No bootstrap required, opened a new log
I20260812 06:19:59.643523 22507 ts_tablet_manager.cc:1403] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:59.644071 22507 raft_consensus.cc:359] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02140ef1ef26479882e029c78fac837f" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 36271 } }
I20260812 06:19:59.644244 22507 raft_consensus.cc:385] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.644337 22507 raft_consensus.cc:740] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 02140ef1ef26479882e029c78fac837f, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.644506 22507 consensus_queue.cc:260] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [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: "02140ef1ef26479882e029c78fac837f" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 36271 } }
I20260812 06:19:59.644630 22507 raft_consensus.cc:399] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.644677 22507 raft_consensus.cc:493] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.644729 22507 raft_consensus.cc:3060] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.645754 22507 raft_consensus.cc:515] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02140ef1ef26479882e029c78fac837f" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 36271 } }
I20260812 06:19:59.645907 22507 leader_election.cc:304] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [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: 02140ef1ef26479882e029c78fac837f; no voters: 
I20260812 06:19:59.646143 22507 leader_election.cc:290] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.646497 22507 ts_tablet_manager.cc:1434] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:59.646610 22510 raft_consensus.cc:2804] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.646884 22510 raft_consensus.cc:697] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 1 LEADER]: Becoming Leader. State: Replica: 02140ef1ef26479882e029c78fac837f, State: Running, Role: LEADER
I20260812 06:19:59.646996 22491 heartbeater.cc:499] Master 127.21.172.190:34203 was elected leader, sending a full tablet report...
I20260812 06:19:59.647449 22510 consensus_queue.cc:237] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [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: "02140ef1ef26479882e029c78fac837f" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 36271 } }
I20260812 06:19:59.650516 22252 catalog_manager.cc:5719] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f reported cstate change: term changed from 0 to 1, leader changed from <none> to 02140ef1ef26479882e029c78fac837f (127.21.172.129). New cstate: current_term: 1 leader_uuid: "02140ef1ef26479882e029c78fac837f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "02140ef1ef26479882e029c78fac837f" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 36271 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:59.716516 22194 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.024s	sys 0.005s
I20260812 06:19:59.851076 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushMRSOp(d6e40e322bb741658d25ab48a4b29214): perf score=19.054940
I20260812 06:20:00.033002 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushMRSOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.182s	user 0.137s	sys 0.043s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":340,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1053,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45437,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":112,"threads_started":1,"update_count":1500}
I20260812 06:20:00.034474 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling LogGCOp(d6e40e322bb741658d25ab48a4b29214): free 20743880 bytes of WAL
I20260812 06:20:00.034883 22386 log_reader.cc:385] T d6e40e322bb741658d25ab48a4b29214: removed 2 log segments from log reader
I20260812 06:20:00.035008 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000001 (ops 1-6)
I20260812 06:20:00.035120 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000002 (ops 7-11)
I20260812 06:20:00.040665 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: LogGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {}
I20260812 06:20:00.041239 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214): 16411392 bytes on disk
I20260812 06:20:00.041828 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214) 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:00.042258 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:00.070283 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.028s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.070874 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:00.086958 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.087495 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:00.257009 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.169s	user 0.121s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":973,"lbm_read_time_us":12004,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28022,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":336,"threads_started":5,"update_count":2500}
I20260812 06:20:00.257746 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:00.302390 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.044s	user 0.012s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19315,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.303197 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:00.328044 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.019s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.328583 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:00.482656 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.154s	user 0.123s	sys 0.030s 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":200,"lbm_read_time_us":10816,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31680,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:20:00.483243 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:00.527686 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.044s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19478,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.528314 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:00.547242 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.019s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.547744 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:00.686426 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.138s	user 0.117s	sys 0.019s 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":248,"lbm_read_time_us":10498,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28039,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:20:00.687175 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:00.727226 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.040s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.727773 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:00.743464 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.744064 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:00.873075 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.129s	user 0.092s	sys 0.036s 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":796,"lbm_read_time_us":8561,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25209,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":49536,"update_count":2000}
I20260812 06:20:00.873946 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:00.924958 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.051s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17395,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.925526 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:00.936200 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.936703 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:01.081354 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.144s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":578,"lbm_read_time_us":10941,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22750,"lbm_writes_lt_1ms":443,"mutex_wait_us":129,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:01.082150 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:01.127115 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.045s	user 0.017s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19696,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.127595 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:01.236613 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.109s	user 0.092s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":221,"lbm_read_time_us":7893,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19597,"lbm_writes_lt_1ms":343,"mutex_wait_us":40,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":1500}
I20260812 06:20:01.237380 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:01.275419 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.038s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14720,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.276053 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushMRSOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:01.316985 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushMRSOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.041s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1375,"drs_written":1,"lbm_read_time_us":135,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1972,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:01.317917 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214): 447 bytes on disk
I20260812 06:20:01.319049 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.319574 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=3.181125
I20260812 06:20:01.339331 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7533,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:01.339857 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling LogGCOp(d6e40e322bb741658d25ab48a4b29214): free 112239257 bytes of WAL
I20260812 06:20:01.340099 22386 log_reader.cc:385] T d6e40e322bb741658d25ab48a4b29214: removed 11 log segments from log reader
I20260812 06:20:01.340147 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000003 (ops 12-16)
I20260812 06:20:01.340178 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000004 (ops 17-20)
I20260812 06:20:01.340250 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000005 (ops 21-25)
I20260812 06:20:01.340293 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000006 (ops 26-30)
I20260812 06:20:01.340330 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000007 (ops 31-35)
I20260812 06:20:01.340369 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000008 (ops 36-40)
I20260812 06:20:01.340408 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000009 (ops 41-45)
I20260812 06:20:01.340478 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000010 (ops 46-50)
I20260812 06:20:01.340523 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000011 (ops 51-55)
I20260812 06:20:01.340567 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000012 (ops 56-60)
I20260812 06:20:01.340619 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000013 (ops 61-65)
I20260812 06:20:01.367442 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: LogGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:01.367885 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:01.390415 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5643,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.390944 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:01.402554 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.403286 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:01.599879 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.196s	user 0.150s	sys 0.040s 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":108,"lbm_read_time_us":14489,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40326,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:20:01.600419 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:01.651885 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.051s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21445,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.652396 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:01.664968 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.012s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.665387 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:01.822804 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.157s	user 0.108s	sys 0.049s 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":1571,"lbm_read_time_us":11495,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30437,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:20:01.823385 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=12.110812
I20260812 06:20:01.865063 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.042s	user 0.021s	sys 0.020s Metrics: {"bytes_written":13866409,"delete_count":0,"lbm_write_time_us":17950,"lbm_writes_lt_1ms":341,"reinsert_count":0,"update_count":1690}
I20260812 06:20:01.865702 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.196750
I20260812 06:20:01.874998 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3011,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:20:01.875612 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:02.036496 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.161s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672241,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":502,"lbm_read_time_us":10346,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27414,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:20:02.037118 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:02.092625 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.093281 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:02.119633 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.026s	user 0.013s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.120265 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:02.332898 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.212s	user 0.150s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":14986,"lbm_reads_lt_1ms":564,"lbm_write_time_us":36149,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":84352,"update_count":2500}
I20260812 06:20:02.333633 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:02.387032 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.053s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20665,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.387667 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:02.398553 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.399325 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:02.567804 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.168s	user 0.133s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":11291,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29641,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:20:02.569934 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=10.126437
I20260812 06:20:02.600711 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13652,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.601281 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:02.620519 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.019s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.621069 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:02.742254 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.121s	user 0.088s	sys 0.033s 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":319,"lbm_read_time_us":7484,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23791,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":42112,"update_count":2000}
I20260812 06:20:02.742995 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=11.118625
I20260812 06:20:02.776997 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.034s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14702,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:02.777613 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:02.793192 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:02.793866 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushMRSOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:02.819301 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushMRSOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.025s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1344,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1519,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:02.820046 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling LogGCOp(d6e40e322bb741658d25ab48a4b29214): free 124710356 bytes of WAL
I20260812 06:20:02.820281 22386 log_reader.cc:385] T d6e40e322bb741658d25ab48a4b29214: removed 12 log segments from log reader
I20260812 06:20:02.820324 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000014 (ops 66-70)
I20260812 06:20:02.820353 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000015 (ops 71-75)
I20260812 06:20:02.820417 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000016 (ops 76-80)
I20260812 06:20:02.820451 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000017 (ops 81-85)
I20260812 06:20:02.820493 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000018 (ops 86-90)
I20260812 06:20:02.820550 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000019 (ops 91-95)
I20260812 06:20:02.820590 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000020 (ops 96-100)
I20260812 06:20:02.820634 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000021 (ops 101-105)
I20260812 06:20:02.820675 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000022 (ops 106-110)
I20260812 06:20:02.820715 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000023 (ops 111-115)
I20260812 06:20:02.820755 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000024 (ops 116-120)
I20260812 06:20:02.820793 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000025 (ops 121-125)
I20260812 06:20:02.847476 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: LogGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:20:02.847903 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=4.173312
I20260812 06:20:02.863247 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":5948753,"delete_count":0,"lbm_write_time_us":6176,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:20:02.863730 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.196750
I20260812 06:20:02.873107 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":2914,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:20:02.874189 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:03.039367 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.165s	user 0.128s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877287,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":637,"lbm_read_time_us":10693,"lbm_reads_lt_1ms":666,"lbm_write_time_us":32655,"lbm_writes_lt_1ms":643,"mutex_wait_us":517,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30976,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:20:03.040205 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214): 463 bytes on disk
I20260812 06:20:03.041200 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.041770 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:03.088102 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.046s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20443,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.088683 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:03.105331 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.105962 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:03.282644 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.175s	user 0.109s	sys 0.054s 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":322,"lbm_read_time_us":9760,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32682,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":2500}
I20260812 06:20:03.283263 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:03.352797 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.069s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27984,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.353328 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:03.363885 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.364537 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:03.556855 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.192s	user 0.141s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":807,"lbm_read_time_us":11633,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36058,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:20:03.557389 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:03.610899 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.053s	user 0.044s	sys 0.006s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22057,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.611582 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:03.624660 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.625552 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:03.815346 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.190s	user 0.143s	sys 0.044s 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":1133,"lbm_read_time_us":14717,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32888,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:20:03.817137 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:03.878095 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.061s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19893,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.878826 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:03.895712 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.896423 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:04.075752 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.179s	user 0.103s	sys 0.063s 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":583,"lbm_read_time_us":13109,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26872,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.076359 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:04.142114 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.066s	user 0.038s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21312,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.142860 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:04.161465 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.018s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.162240 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:04.348656 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.186s	user 0.126s	sys 0.057s 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":1040,"lbm_read_time_us":12209,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32835,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:20:04.349318 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=11.118625
I20260812 06:20:04.397050 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.048s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19089,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:04.397526 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:04.409443 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.409900 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:04.419756 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.420265 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushMRSOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:04.459527 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushMRSOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.039s	user 0.034s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1740,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:04.460254 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling LogGCOp(d6e40e322bb741658d25ab48a4b29214): free 132571586 bytes of WAL
I20260812 06:20:04.460490 22386 log_reader.cc:385] T d6e40e322bb741658d25ab48a4b29214: removed 13 log segments from log reader
I20260812 06:20:04.460536 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000026 (ops 126-130)
I20260812 06:20:04.460563 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000027 (ops 131-135)
I20260812 06:20:04.460629 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000028 (ops 136-140)
I20260812 06:20:04.460671 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000029 (ops 141-145)
I20260812 06:20:04.460712 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000030 (ops 146-150)
I20260812 06:20:04.460747 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000031 (ops 151-154)
I20260812 06:20:04.460807 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000032 (ops 155-159)
I20260812 06:20:04.460860 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000033 (ops 160-164)
I20260812 06:20:04.460901 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000034 (ops 165-169)
I20260812 06:20:04.460939 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000035 (ops 170-174)
I20260812 06:20:04.460983 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000036 (ops 175-179)
I20260812 06:20:04.461022 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000037 (ops 180-184)
I20260812 06:20:04.461059 22386 log.cc:1079] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/d6e40e322bb741658d25ab48a4b29214/wal-000000038 (ops 185-188)
I20260812 06:20:04.492580 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: LogGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.032s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:20:04.493067 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214): 492 bytes on disk
I20260812 06:20:04.493544 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: UndoDeltaBlockGCOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.494257 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=3.181125
I20260812 06:20:04.508478 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5130,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.509052 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:04.519129 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3695,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.519671 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:04.761320 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.241s	user 0.143s	sys 0.096s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":753,"lbm_read_time_us":15171,"lbm_reads_lt_1ms":775,"lbm_write_time_us":43406,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:20:04.762184 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=14.095187
I20260812 06:20:04.825234 22194 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.109s	user 1.928s	sys 0.153s
I20260812 06:20:04.830013 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.068s	user 0.038s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":33628,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.830448 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214): perf score=2.188937
I20260812 06:20:04.840456 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: FlushDeltaMemStoresOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.841104 22495 maintenance_manager.cc:419] P 02140ef1ef26479882e029c78fac837f: Scheduling MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214): perf score=1.000000
I20260812 06:20:04.892066 22194 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.001s	sys 0.000s
I20260812 06:20:04.892732 22194 tablet_server.cc:179] TabletServer@127.21.172.129:0 shutting down...
I20260812 06:20:04.976442 22386 maintenance_manager.cc:643] P 02140ef1ef26479882e029c78fac837f: MajorDeltaCompactionOp(d6e40e322bb741658d25ab48a4b29214) complete. Timing: real 0.135s	user 0.102s	sys 0.033s Metrics: {"cfile_cache_hit":275,"cfile_cache_hit_bytes":11242384,"cfile_cache_miss":257,"cfile_cache_miss_bytes":13532307,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1248,"lbm_read_time_us":6104,"lbm_reads_lt_1ms":289,"lbm_write_time_us":25836,"lbm_writes_lt_1ms":543,"mutex_wait_us":348,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45440,"update_count":2500}
I20260812 06:20:04.977664 22194 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:04.978070 22194 tablet_replica.cc:333] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f: stopping tablet replica
I20260812 06:20:04.978314 22194 raft_consensus.cc:2243] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:04.978547 22194 raft_consensus.cc:2272] T d6e40e322bb741658d25ab48a4b29214 P 02140ef1ef26479882e029c78fac837f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:04.993676 22194 tablet_server.cc:196] TabletServer@127.21.172.129:0 shutdown complete.
I20260812 06:20:05.027077 22194 master.cc:562] Master@127.21.172.190:34203 shutting down...
I20260812 06:20:05.031172 22194 raft_consensus.cc:2243] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.031373 22194 raft_consensus.cc:2272] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.031469 22194 tablet_replica.cc:333] T 00000000000000000000000000000000 P be2dbe4d095e4a279bff6e2522dcc11c: stopping tablet replica
I20260812 06:20:05.043929 22194 master.cc:584] Master@127.21.172.190:34203 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5721 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:05.150795 22194 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.172.190:41899
I20260812 06:20:05.151265 22194 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:05.153880 22194 server_base.cc:1061] running on GCE node
W20260812 06:20:05.153995 22542 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:05.154067 22546 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:05.154122 22543 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:05.154415 22194 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:05.154459 22194 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:05.154474 22194 hybrid_clock.cc:648] HybridClock initialized: now 1786515605154474 us; error 0 us; skew 500 ppm
I20260812 06:20:05.155287 22194 webserver.cc:533] Webserver started at http://127.21.172.190:41745/ using document root <none> and password file <none>
I20260812 06:20:05.155480 22194 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:05.155552 22194 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:05.155651 22194 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:05.156073 22194 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/master-0-root/instance:
uuid: "0317b20836ad4ab39dd111ce84f9837e"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-3h5h"
I20260812 06:20:05.157821 22194 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:05.158854 22553 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:05.159196 22194 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:05.159292 22194 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/master-0-root
uuid: "0317b20836ad4ab39dd111ce84f9837e"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-3h5h"
I20260812 06:20:05.159413 22194 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-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:05.167801 22194 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:05.168226 22194 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:05.172680 22194 rpc_server.cc:307] RPC server started. Bound to: 127.21.172.190:41899
I20260812 06:20:05.174464 22648 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.172.190:41899 every 8 connection(s)
I20260812 06:20:05.174893 22649 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:05.176640 22649 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e: Bootstrap starting.
I20260812 06:20:05.177493 22649 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:05.178524 22649 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e: No bootstrap required, opened a new log
I20260812 06:20:05.178946 22649 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0317b20836ad4ab39dd111ce84f9837e" member_type: VOTER }
I20260812 06:20:05.179035 22649 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:05.179057 22649 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0317b20836ad4ab39dd111ce84f9837e, State: Initialized, Role: FOLLOWER
I20260812 06:20:05.179277 22649 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [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: "0317b20836ad4ab39dd111ce84f9837e" member_type: VOTER }
I20260812 06:20:05.179373 22649 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:05.179438 22649 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:05.179500 22649 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:05.180259 22649 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0317b20836ad4ab39dd111ce84f9837e" member_type: VOTER }
I20260812 06:20:05.180410 22649 leader_election.cc:304] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [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: 0317b20836ad4ab39dd111ce84f9837e; no voters: 
I20260812 06:20:05.180641 22649 leader_election.cc:290] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:05.180790 22658 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:05.181087 22658 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 1 LEADER]: Becoming Leader. State: Replica: 0317b20836ad4ab39dd111ce84f9837e, State: Running, Role: LEADER
I20260812 06:20:05.181144 22649 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:05.181232 22658 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [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: "0317b20836ad4ab39dd111ce84f9837e" member_type: VOTER }
I20260812 06:20:05.181746 22660 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0317b20836ad4ab39dd111ce84f9837e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0317b20836ad4ab39dd111ce84f9837e" member_type: VOTER } }
I20260812 06:20:05.181773 22661 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0317b20836ad4ab39dd111ce84f9837e. Latest consensus state: current_term: 1 leader_uuid: "0317b20836ad4ab39dd111ce84f9837e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0317b20836ad4ab39dd111ce84f9837e" member_type: VOTER } }
I20260812 06:20:05.181908 22661 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:05.182144 22660 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:05.182562 22669 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:05.183372 22669 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:05.183648 22194 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:05.185284 22669 catalog_manager.cc:1383] Generated new cluster ID: f583474bd0964edf8aaca5a5e3a4fa04
I20260812 06:20:05.185333 22669 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:05.199452 22669 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:05.200006 22669 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:05.206277 22669 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e: Generated new TSK 0
I20260812 06:20:05.206470 22669 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:05.216097 22194 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:05.218364 22689 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:05.218536 22194 server_base.cc:1061] running on GCE node
W20260812 06:20:05.218366 22691 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:05.218364 22688 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:05.218843 22194 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:05.218886 22194 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:05.218902 22194 hybrid_clock.cc:648] HybridClock initialized: now 1786515605218902 us; error 0 us; skew 500 ppm
I20260812 06:20:05.219842 22194 webserver.cc:533] Webserver started at http://127.21.172.129:41619/ using document root <none> and password file <none>
I20260812 06:20:05.220032 22194 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:05.220093 22194 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:05.220176 22194 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:05.220573 22194 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/instance:
uuid: "b4d41a6b96ff45c7bff95240e558d1f4"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-3h5h"
I20260812 06:20:05.222344 22194 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:05.223507 22698 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:05.223816 22194 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:05.223883 22194 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root
uuid: "b4d41a6b96ff45c7bff95240e558d1f4"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-3h5h"
I20260812 06:20:05.223973 22194 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-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:05.239136 22194 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:05.239562 22194 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:05.239914 22194 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:05.240401 22194 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:05.240463 22194 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:05.240525 22194 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:05.240576 22194 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:05.244949 22194 rpc_server.cc:307] RPC server started. Bound to: 127.21.172.129:35747
I20260812 06:20:05.246414 22799 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.172.129:35747 every 8 connection(s)
I20260812 06:20:05.257303 22800 heartbeater.cc:344] Connected to a master server at 127.21.172.190:41899
I20260812 06:20:05.257477 22800 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:05.257795 22800 heartbeater.cc:507] Master 127.21.172.190:41899 requested a full tablet report, sending...
I20260812 06:20:05.258565 22590 ts_manager.cc:194] Registered new tserver with Master: b4d41a6b96ff45c7bff95240e558d1f4 (127.21.172.129:35747)
I20260812 06:20:05.259102 22194 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013294385s
I20260812 06:20:05.259395 22590 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56434
I20260812 06:20:05.267006 22590 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56446:
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:05.276576 22741 tablet_service.cc:1511] Processing CreateTablet for tablet 336ba5582087423abbebc9ba8b5d2e67 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c549e15a9c664686b1bf5dd37006bb1c]), partition=
I20260812 06:20:05.276960 22741 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 336ba5582087423abbebc9ba8b5d2e67. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:05.279340 22822 tablet_bootstrap.cc:492] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Bootstrap starting.
I20260812 06:20:05.280252 22822 tablet_bootstrap.cc:654] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:05.281540 22822 tablet_bootstrap.cc:492] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: No bootstrap required, opened a new log
I20260812 06:20:05.281641 22822 ts_tablet_manager.cc:1403] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:05.282225 22822 raft_consensus.cc:359] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b4d41a6b96ff45c7bff95240e558d1f4" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 35747 } }
I20260812 06:20:05.282312 22822 raft_consensus.cc:385] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:05.282333 22822 raft_consensus.cc:740] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b4d41a6b96ff45c7bff95240e558d1f4, State: Initialized, Role: FOLLOWER
I20260812 06:20:05.282491 22822 consensus_queue.cc:260] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [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: "b4d41a6b96ff45c7bff95240e558d1f4" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 35747 } }
I20260812 06:20:05.282593 22822 raft_consensus.cc:399] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:05.282658 22822 raft_consensus.cc:493] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:05.282717 22822 raft_consensus.cc:3060] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:05.283521 22822 raft_consensus.cc:515] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b4d41a6b96ff45c7bff95240e558d1f4" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 35747 } }
I20260812 06:20:05.283643 22822 leader_election.cc:304] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [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: b4d41a6b96ff45c7bff95240e558d1f4; no voters: 
I20260812 06:20:05.283890 22822 leader_election.cc:290] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:05.284119 22828 raft_consensus.cc:2804] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:05.284241 22828 raft_consensus.cc:697] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 1 LEADER]: Becoming Leader. State: Replica: b4d41a6b96ff45c7bff95240e558d1f4, State: Running, Role: LEADER
I20260812 06:20:05.284265 22822 ts_tablet_manager.cc:1434] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:05.284309 22800 heartbeater.cc:499] Master 127.21.172.190:41899 was elected leader, sending a full tablet report...
I20260812 06:20:05.284382 22828 consensus_queue.cc:237] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [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: "b4d41a6b96ff45c7bff95240e558d1f4" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 35747 } }
I20260812 06:20:05.285881 22590 catalog_manager.cc:5719] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 reported cstate change: term changed from 0 to 1, leader changed from <none> to b4d41a6b96ff45c7bff95240e558d1f4 (127.21.172.129). New cstate: current_term: 1 leader_uuid: "b4d41a6b96ff45c7bff95240e558d1f4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b4d41a6b96ff45c7bff95240e558d1f4" member_type: VOTER last_known_addr { host: "127.21.172.129" port: 35747 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:05.346544 22194 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.008s	sys 0.016s
I20260812 06:20:05.496974 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67): perf score=19.054940
I20260812 06:20:05.644884 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.147s	user 0.111s	sys 0.032s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":906,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38754,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:05.645532 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling LogGCOp(336ba5582087423abbebc9ba8b5d2e67): free 20743880 bytes of WAL
I20260812 06:20:05.645784 22703 log_reader.cc:385] T 336ba5582087423abbebc9ba8b5d2e67: removed 2 log segments from log reader
I20260812 06:20:05.645831 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000001 (ops 1-6)
I20260812 06:20:05.645862 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000002 (ops 7-11)
I20260812 06:20:05.650432 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: LogGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:05.650842 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:05.673141 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.673766 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67): 16411393 bytes on disk
I20260812 06:20:05.674186 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.674924 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:05.841044 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.166s	user 0.106s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":581,"lbm_read_time_us":11212,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23825,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":367,"threads_started":5,"update_count":2000}
I20260812 06:20:05.841560 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:05.892053 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.050s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20865,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.892622 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:05.905669 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.906381 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:06.051674 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.145s	user 0.110s	sys 0.032s 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":107,"lbm_read_time_us":9511,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28046,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:20:06.052461 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=11.118625
I20260812 06:20:06.096158 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.043s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19385,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.096820 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.123361 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5549,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":450}
I20260812 06:20:06.123919 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.135915 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.136524 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:06.306519 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.170s	user 0.122s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":249,"lbm_read_time_us":11924,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34086,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:20:06.307327 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=11.118625
I20260812 06:20:06.341209 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.034s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14259,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.341776 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.363503 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.022s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.364013 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.374827 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.375399 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:06.537285 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.162s	user 0.118s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":408,"lbm_read_time_us":12433,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30159,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:20:06.538012 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=10.126437
I20260812 06:20:06.573343 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.035s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":14796,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.574141 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.602754 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.028s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7768,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":500}
I20260812 06:20:06.603219 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.613689 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.614219 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:06.806669 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.192s	user 0.102s	sys 0.078s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774813,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":289,"lbm_read_time_us":13055,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30935,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:20:06.807489 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:06.880985 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.073s	user 0.032s	sys 0.036s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":31580,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.881500 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:06.894883 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.895427 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:06.923683 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1517,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1781,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:06.924238 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling LogGCOp(336ba5582087423abbebc9ba8b5d2e67): free 120553376 bytes of WAL
I20260812 06:20:06.924463 22703 log_reader.cc:385] T 336ba5582087423abbebc9ba8b5d2e67: removed 12 log segments from log reader
I20260812 06:20:06.924504 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000003 (ops 12-16)
I20260812 06:20:06.924623 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000004 (ops 17-21)
I20260812 06:20:06.924652 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000005 (ops 22-26)
I20260812 06:20:06.924691 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000006 (ops 27-30)
I20260812 06:20:06.924733 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000007 (ops 31-35)
I20260812 06:20:06.924773 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000008 (ops 36-40)
I20260812 06:20:06.924811 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000009 (ops 41-45)
I20260812 06:20:06.924872 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000010 (ops 46-50)
I20260812 06:20:06.924914 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000011 (ops 51-54)
I20260812 06:20:06.924954 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000012 (ops 55-59)
I20260812 06:20:06.925002 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000013 (ops 60-64)
I20260812 06:20:06.925068 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000014 (ops 65-69)
I20260812 06:20:06.951783 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: LogGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:20:06.952443 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=4.173312
I20260812 06:20:06.965984 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.013s	user 0.008s	sys 0.005s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":5289,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:20:06.966455 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67): 463 bytes on disk
I20260812 06:20:06.966884 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67) 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:06.967306 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.196750
I20260812 06:20:06.976197 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.009s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":2767,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:20:06.976679 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:07.195744 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.219s	user 0.147s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":251,"lbm_read_time_us":15942,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40612,"lbm_writes_lt_1ms":743,"mutex_wait_us":74,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:20:07.196431 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=18.063937
I20260812 06:20:07.259220 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.063s	user 0.049s	sys 0.012s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":28331,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:07.259662 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:07.271267 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.271790 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:07.443446 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.171s	user 0.147s	sys 0.024s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":13216,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35432,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":111872,"update_count":3000}
I20260812 06:20:07.444015 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:07.495828 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.052s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21349,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.496536 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:07.513270 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.017s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.513814 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:07.683108 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.169s	user 0.123s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1502,"lbm_read_time_us":11907,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31290,"lbm_writes_lt_1ms":543,"mutex_wait_us":398,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:20:07.683830 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:07.741205 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.057s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20024,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.741812 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:07.752624 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.753461 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:07.936404 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.183s	user 0.108s	sys 0.066s 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":699,"lbm_read_time_us":12669,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30371,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:20:07.937067 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:07.998713 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.061s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20553,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.999308 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:08.011961 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.012640 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:08.195811 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.183s	user 0.124s	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":370,"lbm_read_time_us":13533,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33254,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:08.196583 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=11.118625
I20260812 06:20:08.232301 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.036s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15433,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:08.232914 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:08.267303 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.034s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6970,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:08.267844 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:08.279791 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.280397 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:08.313411 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1523,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1674,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:08.314106 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling LogGCOp(336ba5582087423abbebc9ba8b5d2e67): free 112239324 bytes of WAL
I20260812 06:20:08.314369 22703 log_reader.cc:385] T 336ba5582087423abbebc9ba8b5d2e67: removed 11 log segments from log reader
I20260812 06:20:08.314419 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000015 (ops 70-74)
I20260812 06:20:08.314450 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000016 (ops 75-79)
I20260812 06:20:08.314527 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000017 (ops 80-84)
I20260812 06:20:08.314577 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000018 (ops 85-89)
I20260812 06:20:08.314648 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000019 (ops 90-94)
I20260812 06:20:08.314713 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000020 (ops 95-98)
I20260812 06:20:08.314757 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000021 (ops 99-103)
I20260812 06:20:08.314802 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000022 (ops 104-108)
I20260812 06:20:08.314846 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000023 (ops 109-113)
I20260812 06:20:08.314889 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000024 (ops 114-118)
I20260812 06:20:08.314932 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000025 (ops 119-123)
I20260812 06:20:08.341876 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: LogGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:08.342514 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67): 447 bytes on disk
I20260812 06:20:08.343070 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:20:08.343658 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=3.181125
I20260812 06:20:08.356581 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4920,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:08.357079 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:08.367306 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:08.367767 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:08.593385 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.225s	user 0.158s	sys 0.061s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979847,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":583,"lbm_read_time_us":15517,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38881,"lbm_writes_lt_1ms":743,"mutex_wait_us":111,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:20:08.594274 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=18.063937
I20260812 06:20:08.661224 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.067s	user 0.047s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30444,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:08.661736 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:08.673462 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.673878 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:08.830458 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.156s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":10571,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31890,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":3000}
I20260812 06:20:08.831172 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:08.883314 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.051s	user 0.046s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22918,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.883827 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:08.899236 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.899824 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:09.078969 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.179s	user 0.150s	sys 0.026s 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":395,"lbm_read_time_us":10926,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35026,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:09.079703 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:09.132009 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.052s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23182,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.132544 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:09.312620 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.180s	user 0.107s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":238,"lbm_read_time_us":9039,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28660,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:20:09.316884 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:09.380049 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.063s	user 0.042s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27365,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.381021 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:09.404726 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.405252 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:09.584438 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.179s	user 0.102s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":11313,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29277,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:20:09.585180 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:09.643177 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.058s	user 0.043s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27769,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.643671 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:09.665254 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.021s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.665735 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:09.676982 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.677640 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:09.717691 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushMRSOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.040s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":138,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1546,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1885,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:09.718600 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling LogGCOp(336ba5582087423abbebc9ba8b5d2e67): free 120100558 bytes of WAL
I20260812 06:20:09.718885 22703 log_reader.cc:385] T 336ba5582087423abbebc9ba8b5d2e67: removed 12 log segments from log reader
I20260812 06:20:09.718961 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000026 (ops 124-128)
I20260812 06:20:09.719012 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000027 (ops 129-132)
I20260812 06:20:09.719071 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000028 (ops 133-137)
I20260812 06:20:09.719112 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000029 (ops 138-142)
I20260812 06:20:09.719157 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000030 (ops 143-147)
I20260812 06:20:09.719199 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000031 (ops 148-152)
I20260812 06:20:09.719238 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000032 (ops 153-157)
I20260812 06:20:09.719285 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000033 (ops 158-162)
I20260812 06:20:09.719326 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000034 (ops 163-166)
I20260812 06:20:09.719362 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000035 (ops 167-171)
I20260812 06:20:09.719403 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000036 (ops 172-176)
I20260812 06:20:09.719444 22703 log.cc:1079] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: Deleting log segment in path: /tmp/dist-test-taskMOTTxE/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515599404934-22194-0/minicluster-data/ts-0-root/wals/336ba5582087423abbebc9ba8b5d2e67/wal-000000037 (ops 177-180)
I20260812 06:20:09.745369 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: LogGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:09.745997 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67): 447 bytes on disk
I20260812 06:20:09.746657 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: UndoDeltaBlockGCOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.747697 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:09.768350 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.768970 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=2.188937
I20260812 06:20:09.783896 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.784451 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:10.049914 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.265s	user 0.168s	sys 0.096s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":424,"lbm_read_time_us":18313,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45786,"lbm_writes_lt_1ms":843,"mutex_wait_us":114,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":85,"threads_started":1,"update_count":4000}
I20260812 06:20:10.050843 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=18.063937
I20260812 06:20:10.105986 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24507,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:10.106678 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:10.260725 22194 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.914s	user 1.846s	sys 0.148s
I20260812 06:20:10.273772 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.167s	user 0.100s	sys 0.066s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774573,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":11013,"lbm_reads_lt_1ms":559,"lbm_write_time_us":28687,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:10.274312 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67): perf score=14.095187
I20260812 06:20:10.311266 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: FlushDeltaMemStoresOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.037s	user 0.021s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16439,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.311857 22801 maintenance_manager.cc:419] P b4d41a6b96ff45c7bff95240e558d1f4: Scheduling MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67): perf score=1.000000
I20260812 06:20:10.321617 22194 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.060s	user 0.004s	sys 0.000s
I20260812 06:20:10.322201 22194 tablet_server.cc:179] TabletServer@127.21.172.129:0 shutting down...
I20260812 06:20:10.433386 22703 maintenance_manager.cc:643] P b4d41a6b96ff45c7bff95240e558d1f4: MajorDeltaCompactionOp(336ba5582087423abbebc9ba8b5d2e67) complete. Timing: real 0.121s	user 0.114s	sys 0.008s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":445,"lbm_read_time_us":10679,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25022,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:10.434127 22194 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:10.434393 22194 tablet_replica.cc:333] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4: stopping tablet replica
I20260812 06:20:10.434536 22194 raft_consensus.cc:2243] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:10.434765 22194 raft_consensus.cc:2272] T 336ba5582087423abbebc9ba8b5d2e67 P b4d41a6b96ff45c7bff95240e558d1f4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:10.448746 22194 tablet_server.cc:196] TabletServer@127.21.172.129:0 shutdown complete.
I20260812 06:20:10.474200 22194 master.cc:562] Master@127.21.172.190:41899 shutting down...
I20260812 06:20:10.477720 22194 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:10.477931 22194 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:10.478034 22194 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0317b20836ad4ab39dd111ce84f9837e: stopping tablet replica
I20260812 06:20:10.490407 22194 master.cc:584] Master@127.21.172.190:41899 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5445 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11167 ms total)

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