[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:00.596865 31304 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.146.62:35171
I20260812 06:18:00.597821 31304 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:00.598416 31304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:00.604660 31304 server_base.cc:1061] running on GCE node
W20260812 06:18:00.604828 31314 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:00.604849 31313 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:00.605103 31316 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:00.605520 31304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:00.605624 31304 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:00.605666 31304 hybrid_clock.cc:648] HybridClock initialized: now 1786515480605663 us; error 0 us; skew 500 ppm
I20260812 06:18:00.607265 31304 webserver.cc:533] Webserver started at http://127.30.146.62:39709/ using document root <none> and password file <none>
I20260812 06:18:00.607812 31304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:00.607879 31304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:00.608100 31304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:00.609715 31304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/master-0-root/instance:
uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-nj21"
I20260812 06:18:00.613051 31304 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.004s
I20260812 06:18:00.615082 31326 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.616079 31304 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:00.616181 31304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/master-0-root
uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-nj21"
I20260812 06:18:00.616264 31304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:00.640131 31304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:00.640810 31304 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:00.640971 31304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:00.648242 31304 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.62:35171
I20260812 06:18:00.648241 31416 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.62:35171 every 8 connection(s)
I20260812 06:18:00.650588 31418 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:00.656044 31418 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206: Bootstrap starting.
I20260812 06:18:00.658352 31418 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:00.659200 31418 log.cc:826] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:00.660880 31418 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206: No bootstrap required, opened a new log
I20260812 06:18:00.663614 31418 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206" member_type: VOTER }
I20260812 06:18:00.663818 31418 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:00.663870 31418 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3f8eabdae42a4fd4b58eddcd1a3e8206, State: Initialized, Role: FOLLOWER
I20260812 06:18:00.664410 31418 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [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: "3f8eabdae42a4fd4b58eddcd1a3e8206" member_type: VOTER }
I20260812 06:18:00.664541 31418 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:00.664587 31418 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:00.664671 31418 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:00.665369 31418 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206" member_type: VOTER }
I20260812 06:18:00.665745 31418 leader_election.cc:304] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [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: 3f8eabdae42a4fd4b58eddcd1a3e8206; no voters: 
I20260812 06:18:00.666004 31418 leader_election.cc:290] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:00.666144 31423 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:00.666352 31423 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 1 LEADER]: Becoming Leader. State: Replica: 3f8eabdae42a4fd4b58eddcd1a3e8206, State: Running, Role: LEADER
I20260812 06:18:00.666719 31423 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [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: "3f8eabdae42a4fd4b58eddcd1a3e8206" member_type: VOTER }
I20260812 06:18:00.666903 31418 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:00.668536 31424 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206" member_type: VOTER } }
I20260812 06:18:00.668531 31425 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3f8eabdae42a4fd4b58eddcd1a3e8206. Latest consensus state: current_term: 1 leader_uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f8eabdae42a4fd4b58eddcd1a3e8206" member_type: VOTER } }
I20260812 06:18:00.668668 31424 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:00.668668 31425 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:00.669030 31304 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:00.668998 31440 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:00.671309 31440 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:00.675727 31440 catalog_manager.cc:1383] Generated new cluster ID: 102751a43c0a462396288fdb307d3572
I20260812 06:18:00.675777 31440 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:00.691596 31440 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:00.692453 31440 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:00.703655 31440 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206: Generated new TSK 0
I20260812 06:18:00.704332 31440 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:00.733704 31304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:00.736305 31450 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:00.736404 31452 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:00.736449 31449 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:00.736692 31304 server_base.cc:1061] running on GCE node
I20260812 06:18:00.736883 31304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:00.736924 31304 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:00.736939 31304 hybrid_clock.cc:648] HybridClock initialized: now 1786515480736939 us; error 0 us; skew 500 ppm
I20260812 06:18:00.737809 31304 webserver.cc:533] Webserver started at http://127.30.146.1:36417/ using document root <none> and password file <none>
I20260812 06:18:00.737982 31304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:00.738030 31304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:00.738108 31304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:00.738480 31304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/instance:
uuid: "3b66fcbb96324f638eadb18628c18c54"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-nj21"
I20260812 06:18:00.739934 31304 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:00.740893 31462 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.741137 31304 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:00.741206 31304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root
uuid: "3b66fcbb96324f638eadb18628c18c54"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-nj21"
I20260812 06:18:00.741281 31304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:00.750615 31304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:00.751010 31304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:00.751466 31304 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:00.752336 31304 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:00.752388 31304 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.752455 31304 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:00.752480 31304 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.758839 31304 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.1:40763
I20260812 06:18:00.758874 31566 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.1:40763 every 8 connection(s)
I20260812 06:18:00.768548 31567 heartbeater.cc:344] Connected to a master server at 127.30.146.62:35171
I20260812 06:18:00.768810 31567 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:00.769337 31567 heartbeater.cc:507] Master 127.30.146.62:35171 requested a full tablet report, sending...
I20260812 06:18:00.770753 31352 ts_manager.cc:194] Registered new tserver with Master: 3b66fcbb96324f638eadb18628c18c54 (127.30.146.1:40763)
I20260812 06:18:00.771699 31304 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012269904s
I20260812 06:18:00.771915 31352 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46622
I20260812 06:18:00.780871 31352 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46638:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:00.794836 31512 tablet_service.cc:1511] Processing CreateTablet for tablet 2695e97a493c482685efa480481a0914 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e9621821902a407b8f14ddbe95a0129f]), partition=
I20260812 06:18:00.795291 31512 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2695e97a493c482685efa480481a0914. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:00.797551 31588 tablet_bootstrap.cc:492] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Bootstrap starting.
I20260812 06:18:00.798656 31588 tablet_bootstrap.cc:654] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:00.800007 31588 tablet_bootstrap.cc:492] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: No bootstrap required, opened a new log
I20260812 06:18:00.800135 31588 ts_tablet_manager.cc:1403] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:00.801055 31588 raft_consensus.cc:359] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b66fcbb96324f638eadb18628c18c54" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 40763 } }
I20260812 06:18:00.801199 31588 raft_consensus.cc:385] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:00.801255 31588 raft_consensus.cc:740] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3b66fcbb96324f638eadb18628c18c54, State: Initialized, Role: FOLLOWER
I20260812 06:18:00.801414 31588 consensus_queue.cc:260] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [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: "3b66fcbb96324f638eadb18628c18c54" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 40763 } }
I20260812 06:18:00.801532 31588 raft_consensus.cc:399] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:00.801587 31588 raft_consensus.cc:493] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:00.801649 31588 raft_consensus.cc:3060] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:00.802690 31588 raft_consensus.cc:515] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b66fcbb96324f638eadb18628c18c54" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 40763 } }
I20260812 06:18:00.802875 31588 leader_election.cc:304] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [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: 3b66fcbb96324f638eadb18628c18c54; no voters: 
I20260812 06:18:00.803118 31588 leader_election.cc:290] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:00.803221 31590 raft_consensus.cc:2804] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:00.803422 31590 raft_consensus.cc:697] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 1 LEADER]: Becoming Leader. State: Replica: 3b66fcbb96324f638eadb18628c18c54, State: Running, Role: LEADER
I20260812 06:18:00.803493 31588 ts_tablet_manager.cc:1434] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:18:00.803857 31567 heartbeater.cc:499] Master 127.30.146.62:35171 was elected leader, sending a full tablet report...
I20260812 06:18:00.803622 31590 consensus_queue.cc:237] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [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: "3b66fcbb96324f638eadb18628c18c54" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 40763 } }
I20260812 06:18:00.806751 31352 catalog_manager.cc:5719] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3b66fcbb96324f638eadb18628c18c54 (127.30.146.1). New cstate: current_term: 1 leader_uuid: "3b66fcbb96324f638eadb18628c18c54" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3b66fcbb96324f638eadb18628c18c54" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 40763 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:00.869832 31304 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.017s	sys 0.008s
I20260812 06:18:01.010025 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushMRSOp(2695e97a493c482685efa480481a0914): perf score=19.054940
I20260812 06:18:01.173153 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushMRSOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.163s	user 0.133s	sys 0.028s Metrics: {"bytes_written":12594659,"cfile_init":1,"compiler_manager_pool.queue_time_us":270,"delete_count":0,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":832,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37224,"lbm_writes_lt_1ms":764,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":314112,"thread_start_us":163,"threads_started":1,"update_count":1535}
I20260812 06:18:01.174328 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling LogGCOp(2695e97a493c482685efa480481a0914): free 20743880 bytes of WAL
I20260812 06:18:01.174657 31474 log_reader.cc:385] T 2695e97a493c482685efa480481a0914: removed 2 log segments from log reader
I20260812 06:18:01.174726 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000001 (ops 1-6)
I20260812 06:18:01.174784 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000002 (ops 7-11)
I20260812 06:18:01.179394 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: LogGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:01.179901 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914): 16411395 bytes on disk
I20260812 06:18:01.180864 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":187,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.181455 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:01.199010 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.017s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5780,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:01.199760 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:01.349910 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.150s	user 0.093s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1048,"lbm_read_time_us":9459,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23772,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":391,"threads_started":5,"update_count":2000}
I20260812 06:18:01.350659 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:01.387097 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.036s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12808,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.387586 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:01.404310 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.404726 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:01.522989 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.118s	user 0.101s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":9085,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21829,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.523626 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:01.561807 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.038s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16194,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.562352 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:01.577704 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.578176 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:01.697320 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.119s	user 0.101s	sys 0.017s 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":134,"lbm_read_time_us":6726,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23099,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.697949 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:01.742915 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.045s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15238,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.743403 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:01.753372 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.753773 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:01.895150 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.141s	user 0.093s	sys 0.048s 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":443,"lbm_read_time_us":9596,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23416,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.895592 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:01.936766 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.041s	user 0.028s	sys 0.001s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12411,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.937258 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:01.952244 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.952854 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:02.079082 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.126s	user 0.114s	sys 0.012s 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":774,"lbm_read_time_us":9862,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21703,"lbm_writes_lt_1ms":443,"mutex_wait_us":257,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:18:02.079566 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:02.111294 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.032s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.111800 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:02.123059 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.123601 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:02.244343 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.120s	user 0.100s	sys 0.020s 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":599,"lbm_read_time_us":8949,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21604,"lbm_writes_lt_1ms":443,"mutex_wait_us":256,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:02.244930 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:02.295214 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.050s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16520,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.295869 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:02.306285 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.306802 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushMRSOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:02.343881 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushMRSOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.037s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":294,"dirs.run_wall_time_us":1278,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1645,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:02.344843 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling LogGCOp(2695e97a493c482685efa480481a0914): free 112692374 bytes of WAL
I20260812 06:18:02.345113 31474 log_reader.cc:385] T 2695e97a493c482685efa480481a0914: removed 11 log segments from log reader
I20260812 06:18:02.345175 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000003 (ops 12-16)
I20260812 06:18:02.345214 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000004 (ops 17-21)
I20260812 06:18:02.345244 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000005 (ops 22-26)
I20260812 06:18:02.345274 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000006 (ops 27-31)
I20260812 06:18:02.345301 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000007 (ops 32-36)
I20260812 06:18:02.345329 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000008 (ops 37-41)
I20260812 06:18:02.345356 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000009 (ops 42-46)
I20260812 06:18:02.345386 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000010 (ops 47-51)
I20260812 06:18:02.345414 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000011 (ops 52-56)
I20260812 06:18:02.345441 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000012 (ops 57-61)
I20260812 06:18:02.345469 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000013 (ops 62-66)
I20260812 06:18:02.370307 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: LogGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:02.370797 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=3.181125
I20260812 06:18:02.385990 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.015s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5885,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:02.386495 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:02.396597 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3367,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.397145 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914): 446 bytes on disk
I20260812 06:18:02.397653 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.398077 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:02.575482 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.177s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":374,"lbm_read_time_us":9886,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34428,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:18:02.575982 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=14.095187
I20260812 06:18:02.624783 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19936,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.625262 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:02.634878 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.635325 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:02.778316 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.143s	user 0.115s	sys 0.028s 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":119,"lbm_read_time_us":10637,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26551,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:02.778939 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:02.810703 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.032s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12292,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.811183 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:02.829631 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.830169 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:02.972998 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.143s	user 0.079s	sys 0.062s 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":254,"lbm_read_time_us":10205,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24120,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:02.973639 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:03.014003 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.040s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18885,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.014564 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:03.025925 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.026504 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:03.174079 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.147s	user 0.088s	sys 0.054s 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":160,"lbm_read_time_us":7689,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24909,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:03.174654 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:03.205370 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12270,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.205852 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:03.222028 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.222622 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:03.341054 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.118s	user 0.100s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":6769,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23624,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:03.341748 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:03.371012 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.029s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12330,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.371536 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:03.382964 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.383467 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:03.494477 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.111s	user 0.095s	sys 0.015s 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":908,"lbm_read_time_us":7935,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21188,"lbm_writes_lt_1ms":443,"mutex_wait_us":253,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:18:03.495003 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:03.535192 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.040s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15394,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.535779 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:03.545972 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.546396 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:03.686756 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.140s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":558,"lbm_read_time_us":9742,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21225,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2000}
I20260812 06:18:03.689697 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:03.735062 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.045s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15631,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.735592 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:03.750926 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.751583 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushMRSOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:03.784117 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushMRSOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1209,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1838,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1408}
I20260812 06:18:03.784934 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling LogGCOp(2695e97a493c482685efa480481a0914): free 132571311 bytes of WAL
I20260812 06:18:03.785182 31474 log_reader.cc:385] T 2695e97a493c482685efa480481a0914: removed 13 log segments from log reader
I20260812 06:18:03.785233 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000014 (ops 67-71)
I20260812 06:18:03.785271 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000015 (ops 72-76)
I20260812 06:18:03.785317 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000016 (ops 77-80)
I20260812 06:18:03.785343 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000017 (ops 81-85)
I20260812 06:18:03.785374 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000018 (ops 86-90)
I20260812 06:18:03.785404 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000019 (ops 91-95)
I20260812 06:18:03.785434 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000020 (ops 96-100)
I20260812 06:18:03.785465 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000021 (ops 101-104)
I20260812 06:18:03.785496 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000022 (ops 105-109)
I20260812 06:18:03.785526 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000023 (ops 110-114)
I20260812 06:18:03.785557 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000024 (ops 115-119)
I20260812 06:18:03.785588 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000025 (ops 120-124)
I20260812 06:18:03.785619 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000026 (ops 125-129)
I20260812 06:18:03.807696 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: LogGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.023s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:03.808166 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=3.181125
I20260812 06:18:03.825361 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6670,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:03.825830 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:03.840464 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.014s	user 0.007s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3314,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.841017 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:04.036417 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.195s	user 0.098s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":805,"lbm_read_time_us":13233,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33145,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":111,"threads_started":1,"update_count":3000}
I20260812 06:18:04.037066 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914): 482 bytes on disk
I20260812 06:18:04.037806 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.038499 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=14.095187
I20260812 06:18:04.092953 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.054s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19870,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.093552 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:04.103699 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.104142 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:04.268731 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.164s	user 0.106s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":576,"lbm_read_time_us":11951,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27144,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:04.269217 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:04.300007 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.031s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12822,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.300511 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:04.318308 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.018s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.318866 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:04.431824 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.113s	user 0.090s	sys 0.020s 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":942,"lbm_read_time_us":8404,"lbm_reads_lt_1ms":464,"lbm_write_time_us":19923,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":74240,"update_count":2000}
I20260812 06:18:04.432375 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:04.463974 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.031s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12500,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.464457 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:04.476926 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.477588 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:04.603184 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.125s	user 0.114s	sys 0.011s 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":116,"lbm_read_time_us":8964,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21893,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:18:04.603981 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:04.639103 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.035s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13526,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.639652 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:04.651279 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.651979 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:04.781175 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.129s	user 0.108s	sys 0.021s 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":131,"lbm_read_time_us":9312,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24485,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2000}
I20260812 06:18:04.781833 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:04.822638 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.041s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13099,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.823136 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:04.833127 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3721,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.833554 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:04.972980 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.139s	user 0.083s	sys 0.056s 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":682,"lbm_read_time_us":10122,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22470,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.973506 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:05.013983 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.040s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15072,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.014438 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:05.024433 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.025084 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:05.138207 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.113s	user 0.093s	sys 0.020s 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":534,"lbm_read_time_us":8645,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19549,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:18:05.138721 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=10.126437
I20260812 06:18:05.175832 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.037s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16063,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.176409 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:05.191386 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.192019 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushMRSOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:05.224732 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushMRSOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1174,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1509,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:05.225546 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling LogGCOp(2695e97a493c482685efa480481a0914): free 120553586 bytes of WAL
I20260812 06:18:05.225826 31474 log_reader.cc:385] T 2695e97a493c482685efa480481a0914: removed 12 log segments from log reader
I20260812 06:18:05.225883 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000027 (ops 130-134)
I20260812 06:18:05.225924 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000028 (ops 135-139)
I20260812 06:18:05.225958 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000029 (ops 140-144)
I20260812 06:18:05.225991 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000030 (ops 145-149)
I20260812 06:18:05.226028 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000031 (ops 150-154)
I20260812 06:18:05.226060 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000032 (ops 155-159)
I20260812 06:18:05.226091 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000033 (ops 160-164)
I20260812 06:18:05.226118 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000034 (ops 165-168)
I20260812 06:18:05.226147 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000035 (ops 169-173)
I20260812 06:18:05.226179 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000036 (ops 174-178)
I20260812 06:18:05.226209 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000037 (ops 179-182)
I20260812 06:18:05.226239 31474 log.cc:1079] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/2695e97a493c482685efa480481a0914/wal-000000038 (ops 183-187)
I20260812 06:18:05.247195 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: LogGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:05.247637 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=3.181125
I20260812 06:18:05.261010 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:05.261458 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914): 483 bytes on disk
I20260812 06:18:05.261859 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: UndoDeltaBlockGCOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.262432 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=2.188937
I20260812 06:18:05.271301 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3348,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.271817 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914): perf score=1.000000
I20260812 06:18:05.441316 31304 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.571s	user 1.713s	sys 0.100s
I20260812 06:18:05.443442 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: MajorDeltaCompactionOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.171s	user 0.131s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":103,"lbm_read_time_us":10830,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34156,"lbm_writes_lt_1ms":643,"mutex_wait_us":19,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":53760,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:18:05.444314 31568 maintenance_manager.cc:419] P 3b66fcbb96324f638eadb18628c18c54: Scheduling FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914): perf score=14.095187
I20260812 06:18:05.467605 31304 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.026s	user 0.001s	sys 0.000s
I20260812 06:18:05.468277 31304 tablet_server.cc:179] TabletServer@127.30.146.1:0 shutting down...
I20260812 06:18:05.488004 31474 maintenance_manager.cc:643] P 3b66fcbb96324f638eadb18628c18c54: FlushDeltaMemStoresOp(2695e97a493c482685efa480481a0914) complete. Timing: real 0.043s	user 0.032s	sys 0.010s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18128,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.489012 31304 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:05.489401 31304 tablet_replica.cc:333] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54: stopping tablet replica
I20260812 06:18:05.489637 31304 raft_consensus.cc:2243] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.489866 31304 raft_consensus.cc:2272] T 2695e97a493c482685efa480481a0914 P 3b66fcbb96324f638eadb18628c18c54 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.504557 31304 tablet_server.cc:196] TabletServer@127.30.146.1:0 shutdown complete.
I20260812 06:18:05.508874 31304 master.cc:562] Master@127.30.146.62:35171 shutting down...
I20260812 06:18:05.511926 31304 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.512060 31304 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.512130 31304 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3f8eabdae42a4fd4b58eddcd1a3e8206: stopping tablet replica
I20260812 06:18:05.524123 31304 master.cc:584] Master@127.30.146.62:35171 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4999 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:05.595712 31304 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.146.62:37661
I20260812 06:18:05.596112 31304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:05.597930 31623 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:05.598001 31628 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:05.597934 31621 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:05.598109 31304 server_base.cc:1061] running on GCE node
I20260812 06:18:05.598276 31304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:05.598307 31304 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:05.598320 31304 hybrid_clock.cc:648] HybridClock initialized: now 1786515485598320 us; error 0 us; skew 500 ppm
I20260812 06:18:05.599082 31304 webserver.cc:533] Webserver started at http://127.30.146.62:37879/ using document root <none> and password file <none>
I20260812 06:18:05.599228 31304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:05.599282 31304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:05.599359 31304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:05.599908 31304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/master-0-root/instance:
uuid: "e080ef1d18d845839ced5ad6b15fd8e0"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-nj21"
I20260812 06:18:05.601295 31304 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:05.602115 31637 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.602335 31304 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:05.602401 31304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/master-0-root
uuid: "e080ef1d18d845839ced5ad6b15fd8e0"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-nj21"
I20260812 06:18:05.602470 31304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:05.610204 31304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:05.610498 31304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:05.614262 31304 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.62:37661
I20260812 06:18:05.626219 31719 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.62:37661 every 8 connection(s)
I20260812 06:18:05.626788 31720 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:05.628748 31720 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0: Bootstrap starting.
I20260812 06:18:05.629565 31720 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:05.630568 31720 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0: No bootstrap required, opened a new log
I20260812 06:18:05.630975 31720 raft_consensus.cc:359] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e080ef1d18d845839ced5ad6b15fd8e0" member_type: VOTER }
I20260812 06:18:05.631071 31720 raft_consensus.cc:385] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:05.631108 31720 raft_consensus.cc:740] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e080ef1d18d845839ced5ad6b15fd8e0, State: Initialized, Role: FOLLOWER
I20260812 06:18:05.631264 31720 consensus_queue.cc:260] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [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: "e080ef1d18d845839ced5ad6b15fd8e0" member_type: VOTER }
I20260812 06:18:05.631347 31720 raft_consensus.cc:399] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:05.631392 31720 raft_consensus.cc:493] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:05.631448 31720 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:05.632380 31720 raft_consensus.cc:515] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e080ef1d18d845839ced5ad6b15fd8e0" member_type: VOTER }
I20260812 06:18:05.632525 31720 leader_election.cc:304] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [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: e080ef1d18d845839ced5ad6b15fd8e0; no voters: 
I20260812 06:18:05.632725 31720 leader_election.cc:290] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:05.632817 31725 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:05.633023 31725 raft_consensus.cc:697] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 1 LEADER]: Becoming Leader. State: Replica: e080ef1d18d845839ced5ad6b15fd8e0, State: Running, Role: LEADER
I20260812 06:18:05.633155 31725 consensus_queue.cc:237] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [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: "e080ef1d18d845839ced5ad6b15fd8e0" member_type: VOTER }
I20260812 06:18:05.633186 31720 sys_catalog.cc:565] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:05.633577 31726 sys_catalog.cc:455] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e080ef1d18d845839ced5ad6b15fd8e0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e080ef1d18d845839ced5ad6b15fd8e0" member_type: VOTER } }
I20260812 06:18:05.633605 31727 sys_catalog.cc:455] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e080ef1d18d845839ced5ad6b15fd8e0. Latest consensus state: current_term: 1 leader_uuid: "e080ef1d18d845839ced5ad6b15fd8e0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e080ef1d18d845839ced5ad6b15fd8e0" member_type: VOTER } }
I20260812 06:18:05.633749 31727 sys_catalog.cc:458] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:05.633997 31726 sys_catalog.cc:458] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:05.634244 31730 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:05.635002 31730 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:05.635183 31304 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:05.636794 31730 catalog_manager.cc:1383] Generated new cluster ID: 501f2685eb42455a9347cc7ba9861f98
I20260812 06:18:05.636865 31730 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:05.640595 31730 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:05.641196 31730 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:05.648608 31730 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0: Generated new TSK 0
I20260812 06:18:05.648769 31730 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:05.651266 31304 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:05.653183 31762 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:05.653194 31757 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:05.653295 31304 server_base.cc:1061] running on GCE node
W20260812 06:18:05.653198 31756 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:05.653631 31304 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:05.653673 31304 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:05.653687 31304 hybrid_clock.cc:648] HybridClock initialized: now 1786515485653687 us; error 0 us; skew 500 ppm
I20260812 06:18:05.654500 31304 webserver.cc:533] Webserver started at http://127.30.146.1:34131/ using document root <none> and password file <none>
I20260812 06:18:05.654625 31304 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:05.654667 31304 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:05.654721 31304 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:05.655087 31304 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/instance:
uuid: "a417d506a1444476b14bd5d7678a6d3c"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-nj21"
I20260812 06:18:05.656527 31304 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:05.657404 31776 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.657649 31304 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:05.657713 31304 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root
uuid: "a417d506a1444476b14bd5d7678a6d3c"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-nj21"
I20260812 06:18:05.657783 31304 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:05.664121 31304 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:05.664418 31304 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:05.664671 31304 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:05.665095 31304 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:05.665132 31304 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.665171 31304 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:05.665198 31304 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.669059 31304 rpc_server.cc:307] RPC server started. Bound to: 127.30.146.1:32863
I20260812 06:18:05.669113 31890 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.146.1:32863 every 8 connection(s)
I20260812 06:18:05.676564 31891 heartbeater.cc:344] Connected to a master server at 127.30.146.62:37661
I20260812 06:18:05.676678 31891 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:05.676893 31891 heartbeater.cc:507] Master 127.30.146.62:37661 requested a full tablet report, sending...
I20260812 06:18:05.677570 31664 ts_manager.cc:194] Registered new tserver with Master: a417d506a1444476b14bd5d7678a6d3c (127.30.146.1:32863)
I20260812 06:18:05.678212 31304 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008746132s
I20260812 06:18:05.678574 31664 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43452
I20260812 06:18:05.684930 31664 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43456:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:05.693303 31817 tablet_service.cc:1511] Processing CreateTablet for tablet b197b7c25e0c453f8bb5258eb9d6a630 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8f85f29012b64ba4867771673f40befc]), partition=
I20260812 06:18:05.693572 31817 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b197b7c25e0c453f8bb5258eb9d6a630. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:05.695556 31909 tablet_bootstrap.cc:492] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Bootstrap starting.
I20260812 06:18:05.696446 31909 tablet_bootstrap.cc:654] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:05.697503 31909 tablet_bootstrap.cc:492] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: No bootstrap required, opened a new log
I20260812 06:18:05.697585 31909 ts_tablet_manager.cc:1403] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:05.698046 31909 raft_consensus.cc:359] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a417d506a1444476b14bd5d7678a6d3c" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 32863 } }
I20260812 06:18:05.698143 31909 raft_consensus.cc:385] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:05.698184 31909 raft_consensus.cc:740] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a417d506a1444476b14bd5d7678a6d3c, State: Initialized, Role: FOLLOWER
I20260812 06:18:05.698331 31909 consensus_queue.cc:260] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [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: "a417d506a1444476b14bd5d7678a6d3c" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 32863 } }
I20260812 06:18:05.698441 31909 raft_consensus.cc:399] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:05.698491 31909 raft_consensus.cc:493] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:05.698547 31909 raft_consensus.cc:3060] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:05.699357 31909 raft_consensus.cc:515] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a417d506a1444476b14bd5d7678a6d3c" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 32863 } }
I20260812 06:18:05.699492 31909 leader_election.cc:304] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [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: a417d506a1444476b14bd5d7678a6d3c; no voters: 
I20260812 06:18:05.699738 31909 leader_election.cc:290] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:05.699798 31914 raft_consensus.cc:2804] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:05.699987 31914 raft_consensus.cc:697] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 1 LEADER]: Becoming Leader. State: Replica: a417d506a1444476b14bd5d7678a6d3c, State: Running, Role: LEADER
I20260812 06:18:05.700089 31891 heartbeater.cc:499] Master 127.30.146.62:37661 was elected leader, sending a full tablet report...
I20260812 06:18:05.700111 31909 ts_tablet_manager.cc:1434] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Time spent starting tablet: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:18:05.700167 31914 consensus_queue.cc:237] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [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: "a417d506a1444476b14bd5d7678a6d3c" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 32863 } }
I20260812 06:18:05.701516 31664 catalog_manager.cc:5719] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c reported cstate change: term changed from 0 to 1, leader changed from <none> to a417d506a1444476b14bd5d7678a6d3c (127.30.146.1). New cstate: current_term: 1 leader_uuid: "a417d506a1444476b14bd5d7678a6d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a417d506a1444476b14bd5d7678a6d3c" member_type: VOTER last_known_addr { host: "127.30.146.1" port: 32863 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:05.758339 31304 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.017s	sys 0.004s
I20260812 06:18:05.919996 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=23.023690
I20260812 06:18:06.072353 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.152s	user 0.115s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":766,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40449,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:06.072995 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630): free 20743880 bytes of WAL
I20260812 06:18:06.073230 31785 log_reader.cc:385] T b197b7c25e0c453f8bb5258eb9d6a630: removed 2 log segments from log reader
I20260812 06:18:06.073280 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000001 (ops 1-6)
I20260812 06:18:06.073308 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000002 (ops 7-11)
I20260812 06:18:06.076634 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:06.076993 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:06.091208 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.092059 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:06.231215 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.139s	user 0.111s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":687,"lbm_read_time_us":10015,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23541,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":347,"threads_started":5,"update_count":2000}
I20260812 06:18:06.231804 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630): 20513815 bytes on disk
I20260812 06:18:06.232254 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630) 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:18:06.232721 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=11.118625
I20260812 06:18:06.265612 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.033s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13857,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.266214 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:06.280306 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.280786 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:06.402268 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.121s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":7486,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22290,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35968,"update_count":2000}
I20260812 06:18:06.402879 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=11.118625
I20260812 06:18:06.439218 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11761,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.439793 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:06.452708 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4658,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.453174 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:06.594750 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.141s	user 0.110s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":770,"lbm_read_time_us":9200,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21322,"lbm_writes_lt_1ms":443,"mutex_wait_us":208,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.595259 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=11.118625
I20260812 06:18:06.628201 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.033s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13331,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.628790 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:06.641717 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.642212 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:06.757687 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.115s	user 0.098s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":6743,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22675,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:18:06.758219 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=11.118625
I20260812 06:18:06.795751 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.037s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15616,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.796365 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:06.808085 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.808672 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:06.926930 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.118s	user 0.102s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":640,"lbm_read_time_us":8464,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22912,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:06.927412 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:06.965911 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.038s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15175,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.966457 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:06.975926 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.976383 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:07.095767 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.119s	user 0.103s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":526,"lbm_read_time_us":8114,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23232,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:07.096333 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:07.143051 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.047s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15030,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.143558 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:07.153389 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3750,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.153800 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:07.181957 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1130,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1344,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:07.182538 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630): 446 bytes on disk
I20260812 06:18:07.182988 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.183411 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:07.321502 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.138s	user 0.084s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":8729,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21038,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:18:07.322049 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630): free 112239306 bytes of WAL
I20260812 06:18:07.322240 31785 log_reader.cc:385] T b197b7c25e0c453f8bb5258eb9d6a630: removed 11 log segments from log reader
I20260812 06:18:07.322283 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000003 (ops 12-16)
I20260812 06:18:07.322326 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000004 (ops 17-21)
I20260812 06:18:07.322358 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000005 (ops 22-26)
I20260812 06:18:07.322391 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000006 (ops 27-30)
I20260812 06:18:07.322420 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000007 (ops 31-35)
I20260812 06:18:07.322451 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000008 (ops 36-40)
I20260812 06:18:07.322481 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000009 (ops 41-45)
I20260812 06:18:07.322511 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000010 (ops 46-50)
I20260812 06:18:07.322541 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000011 (ops 51-55)
I20260812 06:18:07.322572 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000012 (ops 56-60)
I20260812 06:18:07.322602 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000013 (ops 61-65)
I20260812 06:18:07.341651 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.019s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:07.342015 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=14.095187
I20260812 06:18:07.380326 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.038s	user 0.034s	sys 0.003s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16240,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.380932 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:07.408246 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.027s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.408680 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:07.424616 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.016s	user 0.004s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.425180 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:07.611141 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.186s	user 0.124s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1629,"lbm_read_time_us":12807,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30507,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":662784,"update_count":3000}
I20260812 06:18:07.611786 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=14.095187
I20260812 06:18:07.672041 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.060s	user 0.024s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22496,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.672606 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:07.685387 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.685853 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:07.847795 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.162s	user 0.094s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":11150,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24453,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:07.848282 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=11.118625
I20260812 06:18:07.884419 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.036s	user 0.007s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14984,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:07.884882 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:07.906697 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.022s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3881,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.907193 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:07.922379 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.922988 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:08.108045 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.185s	user 0.135s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":627,"lbm_read_time_us":9647,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29401,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2500}
I20260812 06:18:08.108582 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=14.095187
I20260812 06:18:08.151568 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.043s	user 0.026s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16796,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.152161 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:08.167311 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.167963 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:08.315227 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.147s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":628,"lbm_read_time_us":9042,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28822,"lbm_writes_lt_1ms":543,"mutex_wait_us":261,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:18:08.315836 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:08.343791 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.028s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":11890,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.344226 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:08.356753 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.357532 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:08.487607 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.130s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":665,"lbm_read_time_us":9640,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23044,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:18:08.488322 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:08.528283 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.040s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":14438,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:08.528848 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:08.543617 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.544189 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:08.571187 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1563,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1373,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:08.571956 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630): free 120553382 bytes of WAL
I20260812 06:18:08.572166 31785 log_reader.cc:385] T b197b7c25e0c453f8bb5258eb9d6a630: removed 12 log segments from log reader
I20260812 06:18:08.572211 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000014 (ops 66-70)
I20260812 06:18:08.572252 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000015 (ops 71-75)
I20260812 06:18:08.572288 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000016 (ops 76-80)
I20260812 06:18:08.572326 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000017 (ops 81-84)
I20260812 06:18:08.572348 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000018 (ops 85-89)
I20260812 06:18:08.572377 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000019 (ops 90-94)
I20260812 06:18:08.572408 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000020 (ops 95-99)
I20260812 06:18:08.572440 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000021 (ops 100-104)
I20260812 06:18:08.572467 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000022 (ops 105-108)
I20260812 06:18:08.572494 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000023 (ops 109-113)
I20260812 06:18:08.572520 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000024 (ops 114-118)
I20260812 06:18:08.572549 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000025 (ops 119-123)
I20260812 06:18:08.597893 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:08.598332 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=3.181125
I20260812 06:18:08.617620 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6847,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:08.618021 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630): 463 bytes on disk
I20260812 06:18:08.618394 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.618867 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:08.627861 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3269,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.628392 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:08.805932 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.177s	user 0.144s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":984,"lbm_read_time_us":11451,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35378,"lbm_writes_lt_1ms":643,"mutex_wait_us":297,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:18:08.806499 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=14.095187
I20260812 06:18:08.854267 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.048s	user 0.013s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20863,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.854801 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:08.865880 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.866408 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.013913 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.147s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":752,"lbm_read_time_us":9522,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26710,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2500}
I20260812 06:18:09.014555 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=12.110812
I20260812 06:18:09.057869 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.042s	user 0.031s	sys 0.009s Metrics: {"bytes_written":14481770,"delete_count":0,"lbm_write_time_us":18367,"lbm_writes_lt_1ms":356,"mutex_wait_us":387,"reinsert_count":0,"update_count":1765}
I20260812 06:18:09.058444 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.066468 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.008s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":1944,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:18:09.067117 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.215107 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.148s	user 0.092s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":10072,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22216,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:18:09.215657 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=14.095187
I20260812 06:18:09.259590 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.044s	user 0.023s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.260092 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:09.278203 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.018s	user 0.000s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.278708 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.443846 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.165s	user 0.096s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":11949,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27113,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:09.444466 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=11.118625
I20260812 06:18:09.476130 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.031s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13464,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:09.476965 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:09.491024 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5393,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.491529 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.599614 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.108s	user 0.092s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":7043,"lbm_reads_lt_1ms":464,"lbm_write_time_us":19941,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:18:09.600198 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:09.629752 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.029s	user 0.019s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12167,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.630252 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:09.644891 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.645565 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.766808 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.121s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1347,"lbm_read_time_us":7690,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23748,"lbm_writes_lt_1ms":443,"mutex_wait_us":485,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:18:09.767338 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:09.814779 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.047s	user 0.022s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":30141,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:09.815407 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:09.830896 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.831388 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:09.863788 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushMRSOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.032s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1304,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1353,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:09.864585 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630): free 124710496 bytes of WAL
I20260812 06:18:09.864832 31785 log_reader.cc:385] T b197b7c25e0c453f8bb5258eb9d6a630: removed 12 log segments from log reader
I20260812 06:18:09.864880 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000026 (ops 124-128)
I20260812 06:18:09.864920 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000027 (ops 129-133)
I20260812 06:18:09.864951 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000028 (ops 134-138)
I20260812 06:18:09.864990 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000029 (ops 139-143)
I20260812 06:18:09.865013 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000030 (ops 144-148)
I20260812 06:18:09.865033 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000031 (ops 149-153)
I20260812 06:18:09.865053 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000032 (ops 154-158)
I20260812 06:18:09.865074 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000033 (ops 159-163)
I20260812 06:18:09.865096 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000034 (ops 164-168)
I20260812 06:18:09.865119 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000035 (ops 169-173)
I20260812 06:18:09.865142 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000036 (ops 174-178)
I20260812 06:18:09.865163 31785 log.cc:1079] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: Deleting log segment in path: /tmp/dist-test-task5Ad3Xm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515480586394-31304-0/minicluster-data/ts-0-root/wals/b197b7c25e0c453f8bb5258eb9d6a630/wal-000000037 (ops 179-183)
I20260812 06:18:09.887794 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: LogGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.023s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:18:09.888207 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630): 447 bytes on disk
I20260812 06:18:09.888652 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: UndoDeltaBlockGCOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.889266 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=3.181125
I20260812 06:18:09.900489 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:09.900938 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:09.910172 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3413,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.910630 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:10.071707 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.161s	user 0.137s	sys 0.020s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":473,"lbm_read_time_us":13070,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30333,"lbm_writes_lt_1ms":643,"mutex_wait_us":271,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":34304,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:10.072562 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=14.095187
I20260812 06:18:10.124688 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.052s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26358,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.125159 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=2.188937
I20260812 06:18:10.137413 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.138218 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:10.239018 31304 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.481s	user 1.679s	sys 0.110s
I20260812 06:18:10.271953 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.133s	user 0.106s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":8751,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26223,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:10.272650 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=10.126437
I20260812 06:18:10.312661 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: FlushDeltaMemStoresOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17769,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.313167 31892 maintenance_manager.cc:419] P a417d506a1444476b14bd5d7678a6d3c: Scheduling MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630): perf score=1.000000
I20260812 06:18:10.318213 31304 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.001s	sys 0.000s
I20260812 06:18:10.318674 31304 tablet_server.cc:179] TabletServer@127.30.146.1:0 shutting down...
I20260812 06:18:10.411211 31785 maintenance_manager.cc:643] P a417d506a1444476b14bd5d7678a6d3c: MajorDeltaCompactionOp(b197b7c25e0c453f8bb5258eb9d6a630) complete. Timing: real 0.098s	user 0.077s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":321,"lbm_read_time_us":7860,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18007,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":48,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":1500}
I20260812 06:18:10.411886 31304 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:10.412089 31304 tablet_replica.cc:333] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c: stopping tablet replica
I20260812 06:18:10.412225 31304 raft_consensus.cc:2243] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:10.412392 31304 raft_consensus.cc:2272] T b197b7c25e0c453f8bb5258eb9d6a630 P a417d506a1444476b14bd5d7678a6d3c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:10.416736 31304 tablet_server.cc:196] TabletServer@127.30.146.1:0 shutdown complete.
I20260812 06:18:10.442777 31304 master.cc:562] Master@127.30.146.62:37661 shutting down...
I20260812 06:18:10.445725 31304 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:10.445883 31304 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:10.445935 31304 tablet_replica.cc:333] T 00000000000000000000000000000000 P e080ef1d18d845839ced5ad6b15fd8e0: stopping tablet replica
I20260812 06:18:10.457927 31304 master.cc:584] Master@127.30.146.62:37661 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4936 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9936 ms total)

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