[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:20:11.409268 21355 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.218.254:33053
I20260812 06:20:11.410221 21355 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:20:11.410838 21355 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:11.417424 21363 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:11.417443 21367 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:11.417711 21364 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:11.417845 21355 server_base.cc:1061] running on GCE node
I20260812 06:20:11.418268 21355 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:11.418354 21355 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:11.418377 21355 hybrid_clock.cc:648] HybridClock initialized: now 1786515611418376 us; error 0 us; skew 500 ppm
I20260812 06:20:11.420128 21355 webserver.cc:533] Webserver started at http://127.20.218.254:46451/ using document root <none> and password file <none>
I20260812 06:20:11.420607 21355 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:11.420661 21355 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:11.420842 21355 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:11.422359 21355 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/master-0-root/instance:
uuid: "d094620d4cf74182ae26ce38576d9703"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-w4v5"
I20260812 06:20:11.425629 21355 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:11.427557 21379 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:11.428493 21355 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:11.428580 21355 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/master-0-root
uuid: "d094620d4cf74182ae26ce38576d9703"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-w4v5"
I20260812 06:20:11.428653 21355 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-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:11.447700 21355 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:11.448277 21355 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:20:11.448410 21355 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:11.456115 21355 rpc_server.cc:307] RPC server started. Bound to: 127.20.218.254:33053
I20260812 06:20:11.456133 21482 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.218.254:33053 every 8 connection(s)
I20260812 06:20:11.458357 21483 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:11.463904 21483 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703: Bootstrap starting.
I20260812 06:20:11.466262 21483 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:11.467310 21483 log.cc:826] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:11.469138 21483 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703: No bootstrap required, opened a new log
I20260812 06:20:11.471967 21483 raft_consensus.cc:359] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d094620d4cf74182ae26ce38576d9703" member_type: VOTER }
I20260812 06:20:11.472177 21483 raft_consensus.cc:385] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:11.472281 21483 raft_consensus.cc:740] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d094620d4cf74182ae26ce38576d9703, State: Initialized, Role: FOLLOWER
I20260812 06:20:11.472954 21483 consensus_queue.cc:260] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [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: "d094620d4cf74182ae26ce38576d9703" member_type: VOTER }
I20260812 06:20:11.473136 21483 raft_consensus.cc:399] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:11.473228 21483 raft_consensus.cc:493] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:11.473353 21483 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:11.474152 21483 raft_consensus.cc:515] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d094620d4cf74182ae26ce38576d9703" member_type: VOTER }
I20260812 06:20:11.474608 21483 leader_election.cc:304] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [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: d094620d4cf74182ae26ce38576d9703; no voters: 
I20260812 06:20:11.474941 21483 leader_election.cc:290] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:11.475139 21487 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:11.475419 21487 raft_consensus.cc:697] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 1 LEADER]: Becoming Leader. State: Replica: d094620d4cf74182ae26ce38576d9703, State: Running, Role: LEADER
I20260812 06:20:11.475831 21487 consensus_queue.cc:237] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [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: "d094620d4cf74182ae26ce38576d9703" member_type: VOTER }
I20260812 06:20:11.476080 21483 sys_catalog.cc:565] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:11.477656 21493 sys_catalog.cc:455] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d094620d4cf74182ae26ce38576d9703. Latest consensus state: current_term: 1 leader_uuid: "d094620d4cf74182ae26ce38576d9703" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d094620d4cf74182ae26ce38576d9703" member_type: VOTER } }
I20260812 06:20:11.477705 21488 sys_catalog.cc:455] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d094620d4cf74182ae26ce38576d9703" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d094620d4cf74182ae26ce38576d9703" member_type: VOTER } }
I20260812 06:20:11.477777 21493 sys_catalog.cc:458] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:11.477818 21488 sys_catalog.cc:458] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:11.478248 21505 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:11.478477 21355 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:11.480865 21505 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:11.485704 21505 catalog_manager.cc:1383] Generated new cluster ID: e943bfafd1724442b4a5e9ef7435f9b3
I20260812 06:20:11.485790 21505 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:11.490645 21505 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:11.491566 21505 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:11.506342 21505 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703: Generated new TSK 0
I20260812 06:20:11.507010 21505 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:11.511056 21355 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:11.514016 21518 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:11.514111 21525 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:11.514292 21355 server_base.cc:1061] running on GCE node
W20260812 06:20:11.514012 21517 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:11.514510 21355 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:11.514628 21355 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:11.514665 21355 hybrid_clock.cc:648] HybridClock initialized: now 1786515611514663 us; error 0 us; skew 500 ppm
I20260812 06:20:11.515653 21355 webserver.cc:533] Webserver started at http://127.20.218.193:36711/ using document root <none> and password file <none>
I20260812 06:20:11.515831 21355 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:11.515904 21355 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:11.515982 21355 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:11.516413 21355 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/instance:
uuid: "c8dba61275f04693a6fcdfd3ca7b6956"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-w4v5"
I20260812 06:20:11.517904 21355 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:11.518966 21535 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:11.519294 21355 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:11.519385 21355 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root
uuid: "c8dba61275f04693a6fcdfd3ca7b6956"
format_stamp: "Formatted at 2026-08-12 06:20:11 on dist-test-slave-w4v5"
I20260812 06:20:11.519474 21355 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-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:11.526419 21355 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:11.526846 21355 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:11.527412 21355 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:11.528292 21355 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:11.528364 21355 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:11.528431 21355 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:11.528462 21355 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:11.535662 21355 rpc_server.cc:307] RPC server started. Bound to: 127.20.218.193:41655
I20260812 06:20:11.535725 21660 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.218.193:41655 every 8 connection(s)
I20260812 06:20:11.546598 21662 heartbeater.cc:344] Connected to a master server at 127.20.218.254:33053
I20260812 06:20:11.546864 21662 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:11.547346 21662 heartbeater.cc:507] Master 127.20.218.254:33053 requested a full tablet report, sending...
I20260812 06:20:11.548735 21413 ts_manager.cc:194] Registered new tserver with Master: c8dba61275f04693a6fcdfd3ca7b6956 (127.20.218.193:41655)
I20260812 06:20:11.548818 21355 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012502583s
I20260812 06:20:11.549971 21413 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36804
I20260812 06:20:11.558573 21413 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36808:
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:11.573715 21598 tablet_service.cc:1511] Processing CreateTablet for tablet 70ad370998244549af841513aad1b541 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2d348b468c9e4025ab8317927f49934f]), partition=
I20260812 06:20:11.574177 21598 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 70ad370998244549af841513aad1b541. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:11.576736 21690 tablet_bootstrap.cc:492] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Bootstrap starting.
I20260812 06:20:11.577760 21690 tablet_bootstrap.cc:654] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:11.579052 21690 tablet_bootstrap.cc:492] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: No bootstrap required, opened a new log
I20260812 06:20:11.579201 21690 ts_tablet_manager.cc:1403] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:11.579679 21690 raft_consensus.cc:359] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8dba61275f04693a6fcdfd3ca7b6956" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 41655 } }
I20260812 06:20:11.579823 21690 raft_consensus.cc:385] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:11.579914 21690 raft_consensus.cc:740] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c8dba61275f04693a6fcdfd3ca7b6956, State: Initialized, Role: FOLLOWER
I20260812 06:20:11.580101 21690 consensus_queue.cc:260] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [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: "c8dba61275f04693a6fcdfd3ca7b6956" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 41655 } }
I20260812 06:20:11.580238 21690 raft_consensus.cc:399] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:11.580299 21690 raft_consensus.cc:493] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:11.580361 21690 raft_consensus.cc:3060] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:11.581163 21690 raft_consensus.cc:515] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8dba61275f04693a6fcdfd3ca7b6956" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 41655 } }
I20260812 06:20:11.581318 21690 leader_election.cc:304] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [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: c8dba61275f04693a6fcdfd3ca7b6956; no voters: 
I20260812 06:20:11.581569 21690 leader_election.cc:290] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:11.581662 21692 raft_consensus.cc:2804] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:11.581854 21692 raft_consensus.cc:697] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 1 LEADER]: Becoming Leader. State: Replica: c8dba61275f04693a6fcdfd3ca7b6956, State: Running, Role: LEADER
I20260812 06:20:11.581933 21690 ts_tablet_manager.cc:1434] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:11.582244 21662 heartbeater.cc:499] Master 127.20.218.254:33053 was elected leader, sending a full tablet report...
I20260812 06:20:11.582063 21692 consensus_queue.cc:237] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [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: "c8dba61275f04693a6fcdfd3ca7b6956" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 41655 } }
I20260812 06:20:11.585930 21413 catalog_manager.cc:5719] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 reported cstate change: term changed from 0 to 1, leader changed from <none> to c8dba61275f04693a6fcdfd3ca7b6956 (127.20.218.193). New cstate: current_term: 1 leader_uuid: "c8dba61275f04693a6fcdfd3ca7b6956" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8dba61275f04693a6fcdfd3ca7b6956" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 41655 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:11.653056 21355 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.019s	sys 0.008s
I20260812 06:20:11.786724 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushMRSOp(70ad370998244549af841513aad1b541): perf score=19.054940
I20260812 06:20:11.962610 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushMRSOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.176s	user 0.128s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":206,"delete_count":0,"dirs.queue_time_us":202,"dirs.run_cpu_time_us":322,"dirs.run_wall_time_us":889,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44122,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":129,"threads_started":1,"update_count":1500}
I20260812 06:20:11.964016 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling LogGCOp(70ad370998244549af841513aad1b541): free 20743880 bytes of WAL
I20260812 06:20:11.964318 21547 log_reader.cc:385] T 70ad370998244549af841513aad1b541: removed 2 log segments from log reader
I20260812 06:20:11.964385 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000001 (ops 1-6)
I20260812 06:20:11.964438 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000002 (ops 7-11)
I20260812 06:20:11.969952 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: LogGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:11.970327 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=3.181125
I20260812 06:20:11.992962 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.022s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6087,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:11.993399 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:12.007701 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5547,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.008174 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:12.173456 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.165s	user 0.101s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":588,"lbm_read_time_us":11942,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28488,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":285,"threads_started":5,"update_count":2500}
I20260812 06:20:12.174077 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:12.210879 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.037s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15901,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.211326 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:12.226470 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":500}
I20260812 06:20:12.226977 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:12.350984 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.124s	user 0.102s	sys 0.021s 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":155,"lbm_read_time_us":6865,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26748,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:20:12.351595 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:12.393631 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.042s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15574,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.394196 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:12.409448 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.409982 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541): 16411391 bytes on disk
I20260812 06:20:12.410521 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.411139 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:12.535959 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.125s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":323,"lbm_read_time_us":8128,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26104,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.536618 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:12.585211 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.585641 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:12.596825 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.597325 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:12.722406 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.125s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":7833,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24757,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:20:12.723410 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:12.772557 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.049s	user 0.018s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18265,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.773034 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:12.784159 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.784626 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:12.937474 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.153s	user 0.104s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":11103,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26557,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.938169 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:12.982983 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.045s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15332,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:12.983500 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:12.995167 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.995808 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:13.118330 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.122s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":8730,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23813,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2000}
I20260812 06:20:13.118865 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:13.154584 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.036s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14933,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.155383 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:13.175377 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.020s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.175817 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushMRSOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:13.226517 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushMRSOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.051s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2351,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":896}
I20260812 06:20:13.227423 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling LogGCOp(70ad370998244549af841513aad1b541): free 112692365 bytes of WAL
I20260812 06:20:13.227640 21547 log_reader.cc:385] T 70ad370998244549af841513aad1b541: removed 11 log segments from log reader
I20260812 06:20:13.227684 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000003 (ops 12-16)
I20260812 06:20:13.227720 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000004 (ops 17-21)
I20260812 06:20:13.227783 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000005 (ops 22-26)
I20260812 06:20:13.227845 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000006 (ops 27-31)
I20260812 06:20:13.227885 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000007 (ops 32-36)
I20260812 06:20:13.227926 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000008 (ops 37-41)
I20260812 06:20:13.227967 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000009 (ops 42-46)
I20260812 06:20:13.228004 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000010 (ops 47-51)
I20260812 06:20:13.228042 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000011 (ops 52-56)
I20260812 06:20:13.228080 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000012 (ops 57-61)
I20260812 06:20:13.228117 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000013 (ops 62-66)
I20260812 06:20:13.253186 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: LogGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:13.253580 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=7.149875
I20260812 06:20:13.282266 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.028s	user 0.018s	sys 0.007s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12161,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:13.282800 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling LogGCOp(70ad370998244549af841513aad1b541): free 12017927 bytes of WAL
I20260812 06:20:13.283043 21547 log_reader.cc:385] T 70ad370998244549af841513aad1b541: removed 1 log segments from log reader
I20260812 06:20:13.283123 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000014 (ops 67-71)
I20260812 06:20:13.286016 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: LogGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:13.286347 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:13.301261 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5601,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.301728 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541): 473 bytes on disk
I20260812 06:20:13.302452 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:13.302906 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:13.483454 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.180s	user 0.132s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979744,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":463,"lbm_read_time_us":12177,"lbm_reads_lt_1ms":766,"lbm_write_time_us":37993,"lbm_writes_lt_1ms":743,"mutex_wait_us":86,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":94,"threads_started":1,"update_count":3500}
I20260812 06:20:13.484218 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=14.095187
I20260812 06:20:13.531535 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.047s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20296,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.532078 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:13.555068 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.555563 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:13.727577 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.172s	user 0.120s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1105,"lbm_read_time_us":9963,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30109,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:20:13.728096 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=14.095187
I20260812 06:20:13.779024 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.051s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.779567 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:13.790774 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.791301 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:13.960743 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.169s	user 0.102s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":9549,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30278,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2500}
I20260812 06:20:13.961412 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=11.118625
I20260812 06:20:14.002627 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.041s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17375,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:14.003311 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.026510 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.023s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5470,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:20:14.026948 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.037227 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:20:14.037698 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:14.185168 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.147s	user 0.127s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":332,"lbm_read_time_us":11236,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28635,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:20:14.185868 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:14.220623 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.035s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.221199 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.247345 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.026s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.247819 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.258821 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.259342 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:14.399310 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.140s	user 0.104s	sys 0.034s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":164,"lbm_read_time_us":10078,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26204,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:20:14.399916 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:14.439534 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.039s	user 0.014s	sys 0.025s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17310,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.439989 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.450330 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.450798 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:14.577441 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.126s	user 0.099s	sys 0.027s 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":223,"lbm_read_time_us":8901,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25041,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:20:14.578209 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:14.620131 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.042s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15159,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.620657 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.630995 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.631521 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushMRSOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:14.663686 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushMRSOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1199,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1684,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:14.664489 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling LogGCOp(70ad370998244549af841513aad1b541): free 124257261 bytes of WAL
I20260812 06:20:14.664762 21547 log_reader.cc:385] T 70ad370998244549af841513aad1b541: removed 12 log segments from log reader
I20260812 06:20:14.664830 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000015 (ops 72-76)
I20260812 06:20:14.664883 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000016 (ops 77-81)
I20260812 06:20:14.664943 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000017 (ops 82-86)
I20260812 06:20:14.664984 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000018 (ops 87-91)
I20260812 06:20:14.665022 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000019 (ops 92-96)
I20260812 06:20:14.665061 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000020 (ops 97-101)
I20260812 06:20:14.665099 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000021 (ops 102-106)
I20260812 06:20:14.665138 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000022 (ops 107-111)
I20260812 06:20:14.665179 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000023 (ops 112-116)
I20260812 06:20:14.665217 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000024 (ops 117-121)
I20260812 06:20:14.665256 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000025 (ops 122-126)
I20260812 06:20:14.665295 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000026 (ops 127-130)
I20260812 06:20:14.689460 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: LogGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:14.689937 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541): 472 bytes on disk
I20260812 06:20:14.690551 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:20:14.691330 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.708613 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4184708,"delete_count":0,"lbm_write_time_us":6572,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:20:14.709020 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.719358 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:20:14.719835 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:14.894274 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.174s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":713,"lbm_read_time_us":10834,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38717,"lbm_writes_lt_1ms":643,"mutex_wait_us":271,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:20:14.894927 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=14.095187
I20260812 06:20:14.943275 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.048s	user 0.042s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22704,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:14.943930 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:14.957768 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.958179 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:15.102945 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.145s	user 0.126s	sys 0.013s 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":983,"lbm_read_time_us":9803,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29426,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:20:15.103843 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=11.118625
I20260812 06:20:15.139295 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.035s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14851,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:15.139995 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:15.165208 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:15.165670 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:15.175822 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.176209 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:15.375547 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.199s	user 0.157s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":430,"lbm_read_time_us":12429,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35470,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:15.376187 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=11.118625
I20260812 06:20:15.413015 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.036s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15675,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:15.413584 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:15.428115 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5238,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:15.428722 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:15.572849 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.144s	user 0.077s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":108,"lbm_read_time_us":10991,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24288,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:15.573580 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=7.149875
I20260812 06:20:15.607406 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.034s	user 0.017s	sys 0.013s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":12681,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:15.608043 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:15.629609 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6544,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:15.630326 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:15.758188 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.128s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569857,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":8496,"lbm_reads_lt_1ms":372,"lbm_write_time_us":27297,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":44,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":1500}
I20260812 06:20:15.758945 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:15.799796 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.041s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16030,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.800259 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:15.908666 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.108s	user 0.082s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":325,"lbm_read_time_us":5893,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21384,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:20:15.909421 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:15.954351 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.045s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17429,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.954862 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:15.965375 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.966076 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:16.098095 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.132s	user 0.111s	sys 0.020s 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":241,"lbm_read_time_us":9358,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22766,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:16.098778 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=10.126437
I20260812 06:20:16.144171 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.045s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17251,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.144738 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:16.157001 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.157634 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushMRSOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:16.185492 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushMRSOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1300,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1526,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:16.186196 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling LogGCOp(70ad370998244549af841513aad1b541): free 121006699 bytes of WAL
I20260812 06:20:16.186429 21547 log_reader.cc:385] T 70ad370998244549af841513aad1b541: removed 12 log segments from log reader
I20260812 06:20:16.186471 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000027 (ops 131-135)
I20260812 06:20:16.186501 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000028 (ops 136-140)
I20260812 06:20:16.186545 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000029 (ops 141-145)
I20260812 06:20:16.186586 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000030 (ops 146-150)
I20260812 06:20:16.186616 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000031 (ops 151-154)
I20260812 06:20:16.186672 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000032 (ops 155-159)
I20260812 06:20:16.186710 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000033 (ops 160-164)
I20260812 06:20:16.186748 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000034 (ops 165-169)
I20260812 06:20:16.186785 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000035 (ops 170-174)
I20260812 06:20:16.186821 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000036 (ops 175-179)
I20260812 06:20:16.186857 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000037 (ops 180-184)
I20260812 06:20:16.186898 21547 log.cc:1079] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/70ad370998244549af841513aad1b541/wal-000000038 (ops 185-189)
I20260812 06:20:16.213317 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: LogGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:16.213732 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541): 471 bytes on disk
I20260812 06:20:16.214234 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: UndoDeltaBlockGCOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.214754 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:16.230043 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.230436 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=2.188937
I20260812 06:20:16.240836 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.241237 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling MajorDeltaCompactionOp(70ad370998244549af841513aad1b541): perf score=1.000000
I20260812 06:20:16.418643 21355 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.765s	user 1.776s	sys 0.097s
I20260812 06:20:16.421120 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: MajorDeltaCompactionOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.180s	user 0.143s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":655,"lbm_read_time_us":11666,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38008,"lbm_writes_lt_1ms":643,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:20:16.421825 21664 maintenance_manager.cc:419] P c8dba61275f04693a6fcdfd3ca7b6956: Scheduling FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541): perf score=14.095187
I20260812 06:20:16.447185 21355 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.028s	user 0.004s	sys 0.000s
I20260812 06:20:16.447924 21355 tablet_server.cc:179] TabletServer@127.20.218.193:0 shutting down...
I20260812 06:20:16.471385 21547 maintenance_manager.cc:643] P c8dba61275f04693a6fcdfd3ca7b6956: FlushDeltaMemStoresOp(70ad370998244549af841513aad1b541) complete. Timing: real 0.049s	user 0.019s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24596,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:16.472035 21355 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:16.472461 21355 tablet_replica.cc:333] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956: stopping tablet replica
I20260812 06:20:16.472713 21355 raft_consensus.cc:2243] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:16.472952 21355 raft_consensus.cc:2272] T 70ad370998244549af841513aad1b541 P c8dba61275f04693a6fcdfd3ca7b6956 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:16.478830 21355 tablet_server.cc:196] TabletServer@127.20.218.193:0 shutdown complete.
I20260812 06:20:16.483189 21355 master.cc:562] Master@127.20.218.254:33053 shutting down...
I20260812 06:20:16.487216 21355 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:16.487350 21355 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:16.487402 21355 tablet_replica.cc:333] T 00000000000000000000000000000000 P d094620d4cf74182ae26ce38576d9703: stopping tablet replica
I20260812 06:20:16.499657 21355 master.cc:584] Master@127.20.218.254:33053 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5180 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:16.602924 21355 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.218.254:43089
I20260812 06:20:16.603413 21355 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.605410 21720 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:16.605553 21723 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:16.605710 21355 server_base.cc:1061] running on GCE node
W20260812 06:20:16.605825 21725 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:16.606034 21355 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.606074 21355 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:16.606091 21355 hybrid_clock.cc:648] HybridClock initialized: now 1786515616606090 us; error 0 us; skew 500 ppm
I20260812 06:20:16.607053 21355 webserver.cc:533] Webserver started at http://127.20.218.254:38215/ using document root <none> and password file <none>
I20260812 06:20:16.607308 21355 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.607359 21355 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.607461 21355 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.607888 21355 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/master-0-root/instance:
uuid: "d3087311406249c69c12f0b18f001a07"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-w4v5"
I20260812 06:20:16.609516 21355 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:16.610417 21738 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.610778 21355 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:16.610842 21355 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/master-0-root
uuid: "d3087311406249c69c12f0b18f001a07"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-w4v5"
I20260812 06:20:16.610929 21355 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:16.645238 21355 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.645749 21355 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.650758 21355 rpc_server.cc:307] RPC server started. Bound to: 127.20.218.254:43089
I20260812 06:20:16.651651 21832 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.218.254:43089 every 8 connection(s)
I20260812 06:20:16.652088 21836 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:16.653916 21836 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07: Bootstrap starting.
I20260812 06:20:16.654693 21836 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.655748 21836 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07: No bootstrap required, opened a new log
I20260812 06:20:16.656167 21836 raft_consensus.cc:359] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3087311406249c69c12f0b18f001a07" member_type: VOTER }
I20260812 06:20:16.656279 21836 raft_consensus.cc:385] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.656343 21836 raft_consensus.cc:740] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d3087311406249c69c12f0b18f001a07, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.656510 21836 consensus_queue.cc:260] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [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: "d3087311406249c69c12f0b18f001a07" member_type: VOTER }
I20260812 06:20:16.656605 21836 raft_consensus.cc:399] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.656651 21836 raft_consensus.cc:493] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.656704 21836 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.657387 21836 raft_consensus.cc:515] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3087311406249c69c12f0b18f001a07" member_type: VOTER }
I20260812 06:20:16.657546 21836 leader_election.cc:304] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [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: d3087311406249c69c12f0b18f001a07; no voters: 
I20260812 06:20:16.657732 21836 leader_election.cc:290] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.657860 21842 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.658102 21842 raft_consensus.cc:697] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 1 LEADER]: Becoming Leader. State: Replica: d3087311406249c69c12f0b18f001a07, State: Running, Role: LEADER
I20260812 06:20:16.658211 21836 sys_catalog.cc:565] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:16.658257 21842 consensus_queue.cc:237] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [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: "d3087311406249c69c12f0b18f001a07" member_type: VOTER }
I20260812 06:20:16.658735 21846 sys_catalog.cc:455] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d3087311406249c69c12f0b18f001a07" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3087311406249c69c12f0b18f001a07" member_type: VOTER } }
I20260812 06:20:16.658761 21848 sys_catalog.cc:455] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d3087311406249c69c12f0b18f001a07. Latest consensus state: current_term: 1 leader_uuid: "d3087311406249c69c12f0b18f001a07" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3087311406249c69c12f0b18f001a07" member_type: VOTER } }
I20260812 06:20:16.658921 21848 sys_catalog.cc:458] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:16.658903 21846 sys_catalog.cc:458] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:16.659538 21859 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:16.660388 21859 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:16.660554 21355 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:16.662349 21859 catalog_manager.cc:1383] Generated new cluster ID: 7cb8d6ad47e3475fa88f18bff5013fc6
I20260812 06:20:16.662441 21859 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:16.674615 21859 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:16.675206 21859 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:16.680657 21859 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07: Generated new TSK 0
I20260812 06:20:16.680822 21859 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:16.692802 21355 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:16.694876 21881 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:16.694993 21887 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:16.695065 21883 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:16.695305 21355 server_base.cc:1061] running on GCE node
I20260812 06:20:16.695493 21355 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:16.695539 21355 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:16.695586 21355 hybrid_clock.cc:648] HybridClock initialized: now 1786515616695585 us; error 0 us; skew 500 ppm
I20260812 06:20:16.696547 21355 webserver.cc:533] Webserver started at http://127.20.218.193:45835/ using document root <none> and password file <none>
I20260812 06:20:16.696784 21355 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:16.696846 21355 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:16.696946 21355 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:16.697335 21355 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/instance:
uuid: "16c4596f27d3468581beada4dbcc6b38"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-w4v5"
I20260812 06:20:16.698899 21355 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:16.700001 21894 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.700290 21355 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:16.700383 21355 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root
uuid: "16c4596f27d3468581beada4dbcc6b38"
format_stamp: "Formatted at 2026-08-12 06:20:16 on dist-test-slave-w4v5"
I20260812 06:20:16.700474 21355 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:16.713203 21355 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:16.713682 21355 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:16.714002 21355 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:16.714587 21355 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:16.714648 21355 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.714697 21355 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:16.714748 21355 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:16.719000 21355 rpc_server.cc:307] RPC server started. Bound to: 127.20.218.193:36339
I20260812 06:20:16.719040 22028 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.218.193:36339 every 8 connection(s)
I20260812 06:20:16.727902 22032 heartbeater.cc:344] Connected to a master server at 127.20.218.254:43089
I20260812 06:20:16.728029 22032 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:16.728255 22032 heartbeater.cc:507] Master 127.20.218.254:43089 requested a full tablet report, sending...
I20260812 06:20:16.728961 21778 ts_manager.cc:194] Registered new tserver with Master: 16c4596f27d3468581beada4dbcc6b38 (127.20.218.193:36339)
I20260812 06:20:16.729530 21355 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010054582s
I20260812 06:20:16.729717 21778 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55646
I20260812 06:20:16.736970 21778 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55654:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:16.745690 21950 tablet_service.cc:1511] Processing CreateTablet for tablet 00ffee745f5d48e2b23462a3e04bdff9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=93f6a3f6194b4f16b73f732656ad0e57]), partition=
I20260812 06:20:16.746016 21950 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00ffee745f5d48e2b23462a3e04bdff9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:16.748163 22055 tablet_bootstrap.cc:492] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Bootstrap starting.
I20260812 06:20:16.749081 22055 tablet_bootstrap.cc:654] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.750226 22055 tablet_bootstrap.cc:492] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: No bootstrap required, opened a new log
I20260812 06:20:16.750339 22055 ts_tablet_manager.cc:1403] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:16.750923 22055 raft_consensus.cc:359] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "16c4596f27d3468581beada4dbcc6b38" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 36339 } }
I20260812 06:20:16.751048 22055 raft_consensus.cc:385] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.751152 22055 raft_consensus.cc:740] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 16c4596f27d3468581beada4dbcc6b38, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.751336 22055 consensus_queue.cc:260] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [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: "16c4596f27d3468581beada4dbcc6b38" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 36339 } }
I20260812 06:20:16.751442 22055 raft_consensus.cc:399] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.751489 22055 raft_consensus.cc:493] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.751545 22055 raft_consensus.cc:3060] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.752285 22055 raft_consensus.cc:515] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "16c4596f27d3468581beada4dbcc6b38" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 36339 } }
I20260812 06:20:16.752439 22055 leader_election.cc:304] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [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: 16c4596f27d3468581beada4dbcc6b38; no voters: 
I20260812 06:20:16.752650 22055 leader_election.cc:290] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.752863 22057 raft_consensus.cc:2804] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.753060 22055 ts_tablet_manager.cc:1434] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:20:16.753115 22057 raft_consensus.cc:697] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 1 LEADER]: Becoming Leader. State: Replica: 16c4596f27d3468581beada4dbcc6b38, State: Running, Role: LEADER
I20260812 06:20:16.753115 22032 heartbeater.cc:499] Master 127.20.218.254:43089 was elected leader, sending a full tablet report...
I20260812 06:20:16.753300 22057 consensus_queue.cc:237] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [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: "16c4596f27d3468581beada4dbcc6b38" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 36339 } }
I20260812 06:20:16.754802 21778 catalog_manager.cc:5719] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 reported cstate change: term changed from 0 to 1, leader changed from <none> to 16c4596f27d3468581beada4dbcc6b38 (127.20.218.193). New cstate: current_term: 1 leader_uuid: "16c4596f27d3468581beada4dbcc6b38" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "16c4596f27d3468581beada4dbcc6b38" member_type: VOTER last_known_addr { host: "127.20.218.193" port: 36339 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:16.823527 21355 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.019s	sys 0.004s
I20260812 06:20:16.969961 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=19.054940
I20260812 06:20:17.118189 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.148s	user 0.117s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":831,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38068,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:20:17.118839 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling LogGCOp(00ffee745f5d48e2b23462a3e04bdff9): free 20290830 bytes of WAL
I20260812 06:20:17.119139 21905 log_reader.cc:385] T 00ffee745f5d48e2b23462a3e04bdff9: removed 2 log segments from log reader
I20260812 06:20:17.119213 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000001 (ops 1-6)
I20260812 06:20:17.119256 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000002 (ops 7-10)
I20260812 06:20:17.125092 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: LogGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:20:17.125586 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9): 16411391 bytes on disk
I20260812 06:20:17.126108 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.126724 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:17.148404 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.149389 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:17.158890 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.009s	user 0.000s	sys 0.003s Metrics: {"bytes_written":1230906,"delete_count":0,"lbm_write_time_us":1410,"lbm_writes_lt_1ms":33,"reinsert_count":0,"update_count":150}
I20260812 06:20:17.159296 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.196750
I20260812 06:20:17.167161 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.008s	user 0.000s	sys 0.008s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":2971,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:20:17.167536 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:17.357199 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.189s	user 0.122s	sys 0.066s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24774832,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":835,"lbm_read_time_us":14124,"lbm_reads_lt_1ms":570,"lbm_write_time_us":30542,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":327,"threads_started":5,"update_count":2500}
I20260812 06:20:17.357967 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=11.118625
I20260812 06:20:17.394412 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.036s	user 0.014s	sys 0.018s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":16707,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:17.394977 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:17.412899 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6184,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.413468 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:17.535481 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.122s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":570,"lbm_read_time_us":7382,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22998,"lbm_writes_lt_1ms":443,"mutex_wait_us":552,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:20:17.536067 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=10.126437
I20260812 06:20:17.577178 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.041s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17636,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.577808 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:17.592077 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.592599 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:17.730088 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.137s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":766,"lbm_read_time_us":10119,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25048,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:20:17.730854 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=10.126437
I20260812 06:20:17.776010 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.045s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14211,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.776450 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:17.789094 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.789800 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:17.911003 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.121s	user 0.091s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":992,"lbm_read_time_us":7674,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24579,"lbm_writes_lt_1ms":443,"mutex_wait_us":232,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:17.911666 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=10.126437
I20260812 06:20:17.964337 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.052s	user 0.031s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15136,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.964927 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:17.981257 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.981781 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:18.125836 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.144s	user 0.088s	sys 0.055s 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":221,"lbm_read_time_us":11804,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20919,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:20:18.126618 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=10.126437
I20260812 06:20:18.169836 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.043s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14683,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.170305 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:18.181260 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4085,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.182004 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:18.303175 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":959,"lbm_read_time_us":9305,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22565,"lbm_writes_lt_1ms":443,"mutex_wait_us":204,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:20:18.303792 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=10.126437
I20260812 06:20:18.342388 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.038s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":13686,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.342875 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:18.353775 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.354509 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:18.387519 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1364,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1656,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:18.388101 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling LogGCOp(00ffee745f5d48e2b23462a3e04bdff9): free 120553382 bytes of WAL
I20260812 06:20:18.388331 21905 log_reader.cc:385] T 00ffee745f5d48e2b23462a3e04bdff9: removed 12 log segments from log reader
I20260812 06:20:18.388374 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000003 (ops 11-15)
I20260812 06:20:18.388404 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000004 (ops 16-20)
I20260812 06:20:18.388466 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000005 (ops 21-24)
I20260812 06:20:18.388499 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000006 (ops 25-29)
I20260812 06:20:18.388566 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000007 (ops 30-34)
I20260812 06:20:18.388584 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000008 (ops 35-38)
I20260812 06:20:18.388635 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000009 (ops 39-43)
I20260812 06:20:18.388674 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000010 (ops 44-48)
I20260812 06:20:18.388711 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000011 (ops 49-53)
I20260812 06:20:18.388751 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000012 (ops 54-58)
I20260812 06:20:18.388789 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000013 (ops 59-63)
I20260812 06:20:18.388825 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000014 (ops 64-68)
I20260812 06:20:18.415506 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: LogGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:18.415900 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9): 462 bytes on disk
I20260812 06:20:18.416501 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.417002 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=4.173312
I20260812 06:20:18.435694 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":6112848,"delete_count":0,"lbm_write_time_us":7693,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:20:18.436110 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:18.446223 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":3359,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:20:18.446687 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:18.609468 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.163s	user 0.126s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877296,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":720,"lbm_read_time_us":12583,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30617,"lbm_writes_lt_1ms":643,"mutex_wait_us":261,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:18.610155 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=14.095187
I20260812 06:20:18.668373 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.058s	user 0.041s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24371,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:20:18.668963 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:18.683883 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.015s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.684393 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:18.850559 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.166s	user 0.121s	sys 0.036s 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":658,"lbm_read_time_us":10698,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28029,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:20:18.851148 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=14.095187
I20260812 06:20:18.905301 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.054s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24377,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.905751 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:19.045904 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.140s	user 0.083s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":671,"lbm_read_time_us":8629,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23617,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:19.046506 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=11.118625
I20260812 06:20:19.084534 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.038s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12471588,"delete_count":0,"lbm_write_time_us":15628,"lbm_writes_lt_1ms":307,"reinsert_count":0,"update_count":1520}
I20260812 06:20:19.085076 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=3.181125
I20260812 06:20:19.104736 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.019s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":4478,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:20:19.105269 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.118652 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5228,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.119241 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:19.300933 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.181s	user 0.105s	sys 0.071s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":208,"lbm_read_time_us":12629,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30233,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:20:19.301757 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=11.118625
I20260812 06:20:19.337888 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15384,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.338449 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.358388 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.020s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.358870 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.368830 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.369288 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:19.533206 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.164s	user 0.120s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":192,"lbm_read_time_us":10923,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31455,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:20:19.533942 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=11.118625
I20260812 06:20:19.573994 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.040s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16698,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.574549 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.600953 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.026s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5846,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.601496 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.611976 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.010s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.612430 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:19.768198 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.156s	user 0.132s	sys 0.013s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":582,"lbm_read_time_us":10131,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29042,"lbm_writes_lt_1ms":543,"mutex_wait_us":254,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:20:19.768752 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=14.095187
I20260812 06:20:19.824738 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.056s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.826135 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.837790 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4476,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.838346 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:19.869773 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1364,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1605,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1920}
I20260812 06:20:19.870507 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling LogGCOp(00ffee745f5d48e2b23462a3e04bdff9): free 121006448 bytes of WAL
I20260812 06:20:19.870848 21905 log_reader.cc:385] T 00ffee745f5d48e2b23462a3e04bdff9: removed 12 log segments from log reader
I20260812 06:20:19.870913 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000015 (ops 69-73)
I20260812 06:20:19.870951 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000016 (ops 74-78)
I20260812 06:20:19.870981 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000017 (ops 79-83)
I20260812 06:20:19.871013 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000018 (ops 84-88)
I20260812 06:20:19.871042 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000019 (ops 89-93)
I20260812 06:20:19.871065 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000020 (ops 94-98)
I20260812 06:20:19.871116 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000021 (ops 99-103)
I20260812 06:20:19.871152 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000022 (ops 104-108)
I20260812 06:20:19.871183 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000023 (ops 109-112)
I20260812 06:20:19.871217 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000024 (ops 113-117)
I20260812 06:20:19.871248 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000025 (ops 118-122)
I20260812 06:20:19.871276 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000026 (ops 123-127)
I20260812 06:20:19.898862 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: LogGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:19.899468 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9): 482 bytes on disk
I20260812 06:20:19.900120 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.900794 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.920630 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.921206 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:19.931761 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.932271 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:20.174130 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.242s	user 0.165s	sys 0.062s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1194,"lbm_read_time_us":14753,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39633,"lbm_writes_lt_1ms":743,"mutex_wait_us":464,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11776,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:20:20.175283 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=18.063937
I20260812 06:20:20.246860 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.071s	user 0.039s	sys 0.028s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":26778,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:20.247435 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:20.263901 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.016s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.264381 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:20.466018 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.201s	user 0.140s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":858,"lbm_read_time_us":14072,"lbm_reads_lt_1ms":664,"lbm_write_time_us":31829,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":3000}
I20260812 06:20:20.466742 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=16.079562
I20260812 06:20:20.536978 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.070s	user 0.024s	sys 0.031s Metrics: {"bytes_written":17968824,"delete_count":0,"lbm_write_time_us":24943,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":440,"reinsert_count":0,"update_count":2190}
I20260812 06:20:20.537539 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=5.165500
I20260812 06:20:20.562541 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.025s	user 0.015s	sys 0.003s Metrics: {"bytes_written":6646162,"delete_count":0,"lbm_write_time_us":8233,"lbm_writes_lt_1ms":165,"reinsert_count":0,"update_count":810}
I20260812 06:20:20.563119 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:20.770666 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.207s	user 0.135s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":14264,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33635,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":3000}
I20260812 06:20:20.771405 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=18.063937
I20260812 06:20:20.847054 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.075s	user 0.035s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28230,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:20.847664 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:20.861370 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5049,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.862010 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:21.072285 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.210s	user 0.122s	sys 0.086s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":14434,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37639,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:20:21.073132 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=14.095187
I20260812 06:20:21.128069 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.055s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23944,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.128769 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:21.150736 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.022s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.151371 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:21.321861 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.170s	user 0.105s	sys 0.065s 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":192,"lbm_read_time_us":12475,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28256,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:21.322757 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=14.095187
I20260812 06:20:21.380517 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.058s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21506,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.381086 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:21.407969 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.027s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.408510 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:21.419139 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.419586 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:21.453142 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushMRSOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1386,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2085,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:21.453855 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling LogGCOp(00ffee745f5d48e2b23462a3e04bdff9): free 132571592 bytes of WAL
I20260812 06:20:21.454121 21905 log_reader.cc:385] T 00ffee745f5d48e2b23462a3e04bdff9: removed 13 log segments from log reader
I20260812 06:20:21.454183 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000027 (ops 128-132)
I20260812 06:20:21.454219 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000028 (ops 133-136)
I20260812 06:20:21.454252 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000029 (ops 137-141)
I20260812 06:20:21.454285 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000030 (ops 142-146)
I20260812 06:20:21.454319 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000031 (ops 147-151)
I20260812 06:20:21.454341 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000032 (ops 152-156)
I20260812 06:20:21.454362 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000033 (ops 157-161)
I20260812 06:20:21.454391 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000034 (ops 162-166)
I20260812 06:20:21.454420 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000035 (ops 167-171)
I20260812 06:20:21.454455 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000036 (ops 172-176)
I20260812 06:20:21.454486 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000037 (ops 177-181)
I20260812 06:20:21.454514 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000038 (ops 182-186)
I20260812 06:20:21.454543 21905 log.cc:1079] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: Deleting log segment in path: /tmp/dist-test-taskndjMxN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515611398555-21355-0/minicluster-data/ts-0-root/wals/00ffee745f5d48e2b23462a3e04bdff9/wal-000000039 (ops 187-190)
I20260812 06:20:21.485036 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: LogGCOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:21.485630 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9): 482 bytes on disk
I20260812 06:20:21.486073 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: UndoDeltaBlockGCOp(00ffee745f5d48e2b23462a3e04bdff9) 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:21.486619 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:21.509788 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.023s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.510329 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=2.188937
I20260812 06:20:21.521500 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.522172 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=1.000000
I20260812 06:20:21.639417 21355 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.816s	user 1.802s	sys 0.181s
I20260812 06:20:21.746977 21355 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.001s	sys 0.000s
I20260812 06:20:21.747489 21355 tablet_server.cc:179] TabletServer@127.20.218.193:0 shutting down...
I20260812 06:20:21.751515 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: MajorDeltaCompactionOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.229s	user 0.160s	sys 0.068s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082283,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":652,"lbm_read_time_us":17672,"lbm_reads_lt_1ms":871,"lbm_write_time_us":39002,"lbm_writes_lt_1ms":843,"mutex_wait_us":358,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":73,"threads_started":1,"update_count":4000}
I20260812 06:20:21.752435 22034 maintenance_manager.cc:419] P 16c4596f27d3468581beada4dbcc6b38: Scheduling FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9): perf score=10.126437
I20260812 06:20:21.789574 21905 maintenance_manager.cc:643] P 16c4596f27d3468581beada4dbcc6b38: FlushDeltaMemStoresOp(00ffee745f5d48e2b23462a3e04bdff9) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17009,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.790187 21355 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:21.790412 21355 tablet_replica.cc:333] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38: stopping tablet replica
I20260812 06:20:21.790573 21355 raft_consensus.cc:2243] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.790763 21355 raft_consensus.cc:2272] T 00ffee745f5d48e2b23462a3e04bdff9 P 16c4596f27d3468581beada4dbcc6b38 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.804651 21355 tablet_server.cc:196] TabletServer@127.20.218.193:0 shutdown complete.
I20260812 06:20:21.823318 21355 master.cc:562] Master@127.20.218.254:43089 shutting down...
I20260812 06:20:21.827015 21355 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.827261 21355 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.827358 21355 tablet_replica.cc:333] T 00000000000000000000000000000000 P d3087311406249c69c12f0b18f001a07: stopping tablet replica
I20260812 06:20:21.839826 21355 master.cc:584] Master@127.20.218.254:43089 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5335 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10517 ms total)

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