[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:14.477334 26204 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.151.62:37167
I20260812 06:19:14.478329 26204 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:14.478912 26204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:14.484817 26212 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:14.485024 26204 server_base.cc:1061] running on GCE node
W20260812 06:19:14.484952 26211 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:14.485102 26214 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:14.485602 26204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:14.485700 26204 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:14.485743 26204 hybrid_clock.cc:648] HybridClock initialized: now 1786515554485741 us; error 0 us; skew 500 ppm
I20260812 06:19:14.487476 26204 webserver.cc:533] Webserver started at http://127.25.151.62:43927/ using document root <none> and password file <none>
I20260812 06:19:14.488036 26204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:14.488102 26204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:14.488319 26204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:14.489892 26204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/master-0-root/instance:
uuid: "82060b7b5d674807b698266d43d798c6"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-jlzn"
I20260812 06:19:14.493163 26204 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:14.495187 26220 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.496140 26204 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:14.496250 26204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/master-0-root
uuid: "82060b7b5d674807b698266d43d798c6"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-jlzn"
I20260812 06:19:14.496332 26204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:14.506702 26204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:14.507238 26204 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:14.507376 26204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:14.514329 26204 rpc_server.cc:307] RPC server started. Bound to: 127.25.151.62:37167
I20260812 06:19:14.514349 26297 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.151.62:37167 every 8 connection(s)
I20260812 06:19:14.516427 26300 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:14.521472 26300 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6: Bootstrap starting.
I20260812 06:19:14.523626 26300 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:14.524502 26300 log.cc:826] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:14.526062 26300 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6: No bootstrap required, opened a new log
I20260812 06:19:14.528720 26300 raft_consensus.cc:359] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82060b7b5d674807b698266d43d798c6" member_type: VOTER }
I20260812 06:19:14.528872 26300 raft_consensus.cc:385] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:14.528937 26300 raft_consensus.cc:740] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 82060b7b5d674807b698266d43d798c6, State: Initialized, Role: FOLLOWER
I20260812 06:19:14.529469 26300 consensus_queue.cc:260] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [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: "82060b7b5d674807b698266d43d798c6" member_type: VOTER }
I20260812 06:19:14.529623 26300 raft_consensus.cc:399] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:14.529687 26300 raft_consensus.cc:493] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:14.529799 26300 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:14.530507 26300 raft_consensus.cc:515] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82060b7b5d674807b698266d43d798c6" member_type: VOTER }
I20260812 06:19:14.530920 26300 leader_election.cc:304] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [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: 82060b7b5d674807b698266d43d798c6; no voters: 
I20260812 06:19:14.531189 26300 leader_election.cc:290] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:14.531304 26303 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:14.531509 26303 raft_consensus.cc:697] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 1 LEADER]: Becoming Leader. State: Replica: 82060b7b5d674807b698266d43d798c6, State: Running, Role: LEADER
I20260812 06:19:14.531916 26303 consensus_queue.cc:237] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [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: "82060b7b5d674807b698266d43d798c6" member_type: VOTER }
I20260812 06:19:14.532122 26300 sys_catalog.cc:565] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:14.533645 26307 sys_catalog.cc:455] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 82060b7b5d674807b698266d43d798c6. Latest consensus state: current_term: 1 leader_uuid: "82060b7b5d674807b698266d43d798c6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82060b7b5d674807b698266d43d798c6" member_type: VOTER } }
I20260812 06:19:14.533680 26306 sys_catalog.cc:455] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "82060b7b5d674807b698266d43d798c6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "82060b7b5d674807b698266d43d798c6" member_type: VOTER } }
I20260812 06:19:14.533773 26307 sys_catalog.cc:458] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:14.533776 26306 sys_catalog.cc:458] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:14.534209 26322 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:14.534230 26204 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:14.536372 26322 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:14.540472 26322 catalog_manager.cc:1383] Generated new cluster ID: ebc371a0c54b4a6aad6ac26462ba220e
I20260812 06:19:14.540536 26322 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:14.575139 26322 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:14.576402 26322 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:14.583292 26322 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6: Generated new TSK 0
I20260812 06:19:14.584108 26322 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:14.599220 26204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:14.602211 26330 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:14.602344 26334 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:14.602234 26331 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:14.602522 26204 server_base.cc:1061] running on GCE node
I20260812 06:19:14.602813 26204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:14.602855 26204 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:14.602876 26204 hybrid_clock.cc:648] HybridClock initialized: now 1786515554602875 us; error 0 us; skew 500 ppm
I20260812 06:19:14.603901 26204 webserver.cc:533] Webserver started at http://127.25.151.1:43483/ using document root <none> and password file <none>
I20260812 06:19:14.604074 26204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:14.604133 26204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:14.604211 26204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:14.604601 26204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/instance:
uuid: "5d0c7b34ce7e4d17985da64adba41b08"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-jlzn"
I20260812 06:19:14.606105 26204 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:14.607059 26342 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.607323 26204 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:14.607391 26204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root
uuid: "5d0c7b34ce7e4d17985da64adba41b08"
format_stamp: "Formatted at 2026-08-12 06:19:14 on dist-test-slave-jlzn"
I20260812 06:19:14.607461 26204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:14.617728 26204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:14.618160 26204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:14.618606 26204 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:14.619419 26204 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:14.619472 26204 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.619519 26204 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:14.619551 26204 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:14.625784 26204 rpc_server.cc:307] RPC server started. Bound to: 127.25.151.1:39811
I20260812 06:19:14.625826 26440 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.151.1:39811 every 8 connection(s)
I20260812 06:19:14.635273 26441 heartbeater.cc:344] Connected to a master server at 127.25.151.62:37167
I20260812 06:19:14.635483 26441 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:14.635907 26441 heartbeater.cc:507] Master 127.25.151.62:37167 requested a full tablet report, sending...
I20260812 06:19:14.637148 26245 ts_manager.cc:194] Registered new tserver with Master: 5d0c7b34ce7e4d17985da64adba41b08 (127.25.151.1:39811)
I20260812 06:19:14.637491 26204 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011158464s
I20260812 06:19:14.638223 26245 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58858
I20260812 06:19:14.646098 26245 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58860:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:14.658836 26385 tablet_service.cc:1511] Processing CreateTablet for tablet 052ab9e50ce54fa4886fa99144eb5000 (DEFAULT_TABLE table=heavy-update-compaction-test [id=09a9c255f1694d5bacae3d7fcec91304]), partition=
I20260812 06:19:14.659264 26385 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 052ab9e50ce54fa4886fa99144eb5000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:14.661518 26459 tablet_bootstrap.cc:492] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Bootstrap starting.
I20260812 06:19:14.662889 26459 tablet_bootstrap.cc:654] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:14.664161 26459 tablet_bootstrap.cc:492] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: No bootstrap required, opened a new log
I20260812 06:19:14.664268 26459 ts_tablet_manager.cc:1403] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:14.664739 26459 raft_consensus.cc:359] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d0c7b34ce7e4d17985da64adba41b08" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 39811 } }
I20260812 06:19:14.664865 26459 raft_consensus.cc:385] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:14.664904 26459 raft_consensus.cc:740] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5d0c7b34ce7e4d17985da64adba41b08, State: Initialized, Role: FOLLOWER
I20260812 06:19:14.665042 26459 consensus_queue.cc:260] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [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: "5d0c7b34ce7e4d17985da64adba41b08" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 39811 } }
I20260812 06:19:14.665154 26459 raft_consensus.cc:399] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:14.665201 26459 raft_consensus.cc:493] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:14.665248 26459 raft_consensus.cc:3060] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:14.666225 26459 raft_consensus.cc:515] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d0c7b34ce7e4d17985da64adba41b08" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 39811 } }
I20260812 06:19:14.666379 26459 leader_election.cc:304] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [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: 5d0c7b34ce7e4d17985da64adba41b08; no voters: 
I20260812 06:19:14.666579 26459 leader_election.cc:290] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:14.666672 26461 raft_consensus.cc:2804] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:14.666944 26461 raft_consensus.cc:697] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 1 LEADER]: Becoming Leader. State: Replica: 5d0c7b34ce7e4d17985da64adba41b08, State: Running, Role: LEADER
I20260812 06:19:14.667006 26459 ts_tablet_manager.cc:1434] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:14.667145 26461 consensus_queue.cc:237] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [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: "5d0c7b34ce7e4d17985da64adba41b08" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 39811 } }
I20260812 06:19:14.667402 26441 heartbeater.cc:499] Master 127.25.151.62:37167 was elected leader, sending a full tablet report...
I20260812 06:19:14.669957 26245 catalog_manager.cc:5719] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5d0c7b34ce7e4d17985da64adba41b08 (127.25.151.1). New cstate: current_term: 1 leader_uuid: "5d0c7b34ce7e4d17985da64adba41b08" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d0c7b34ce7e4d17985da64adba41b08" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 39811 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:14.737377 26204 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.021s	sys 0.008s
I20260812 06:19:14.876824 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000): perf score=19.054940
I20260812 06:19:15.040132 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.163s	user 0.141s	sys 0.012s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":299,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":868,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37495,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":146,"threads_started":1,"update_count":1500}
I20260812 06:19:15.041244 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling LogGCOp(052ab9e50ce54fa4886fa99144eb5000): free 20743880 bytes of WAL
I20260812 06:19:15.041538 26349 log_reader.cc:385] T 052ab9e50ce54fa4886fa99144eb5000: removed 2 log segments from log reader
I20260812 06:19:15.041605 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000001 (ops 1-6)
I20260812 06:19:15.041712 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000002 (ops 7-11)
I20260812 06:19:15.046242 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: LogGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:15.046641 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000): 16411392 bytes on disk
I20260812 06:19:15.047381 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.047960 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:15.068634 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.069151 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:15.206835 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.138s	user 0.078s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":9239,"lbm_reads_lt_1ms":460,"lbm_write_time_us":20878,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":264,"threads_started":5,"update_count":2000}
I20260812 06:19:15.207429 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=10.126437
I20260812 06:19:15.249526 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18049,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.249985 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:15.261376 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.261773 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:15.371212 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.109s	user 0.092s	sys 0.015s 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":243,"lbm_read_time_us":6600,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22229,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.372089 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=10.126437
I20260812 06:19:15.406399 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.034s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13505,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.406795 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:15.416359 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3616,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.416911 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:15.530659 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.114s	user 0.064s	sys 0.047s 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":211,"lbm_read_time_us":7418,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22577,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:15.531226 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=10.126437
I20260812 06:19:15.579375 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.048s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14400,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.579939 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:15.589824 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.590271 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:15.721851 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.131s	user 0.094s	sys 0.036s 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":120,"lbm_read_time_us":9327,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20696,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":60032,"update_count":2000}
I20260812 06:19:15.722417 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=10.126437
I20260812 06:19:15.767783 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.045s	user 0.016s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13027,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.768285 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:15.778029 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3574,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.778573 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:15.892463 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.114s	user 0.095s	sys 0.017s 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":602,"lbm_read_time_us":8897,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":20441,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29056,"update_count":2000}
I20260812 06:19:15.892959 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=10.126437
I20260812 06:19:15.924629 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13035,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.925113 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:15.939854 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.940421 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:16.055248 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.115s	user 0.098s	sys 0.016s 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":200,"lbm_read_time_us":7709,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22704,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:16.055907 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=10.126437
I20260812 06:19:16.094008 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.038s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.094509 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:16.104568 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.105058 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:16.141232 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.036s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1043,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1191,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:16.142094 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling LogGCOp(052ab9e50ce54fa4886fa99144eb5000): free 112692367 bytes of WAL
I20260812 06:19:16.142333 26349 log_reader.cc:385] T 052ab9e50ce54fa4886fa99144eb5000: removed 11 log segments from log reader
I20260812 06:19:16.142395 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000003 (ops 12-16)
I20260812 06:19:16.142434 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000004 (ops 17-21)
I20260812 06:19:16.142464 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000005 (ops 22-26)
I20260812 06:19:16.142489 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000006 (ops 27-31)
I20260812 06:19:16.142520 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000007 (ops 32-36)
I20260812 06:19:16.142584 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000008 (ops 37-41)
I20260812 06:19:16.142619 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000009 (ops 42-46)
I20260812 06:19:16.142652 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000010 (ops 47-51)
I20260812 06:19:16.142683 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000011 (ops 52-56)
I20260812 06:19:16.142711 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000012 (ops 57-61)
I20260812 06:19:16.142736 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000013 (ops 62-66)
I20260812 06:19:16.165774 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: LogGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.024s	user 0.003s	sys 0.019s Metrics: {}
I20260812 06:19:16.166210 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=3.181125
I20260812 06:19:16.187645 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.021s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:16.188086 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000): 446 bytes on disk
I20260812 06:19:16.188472 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000) 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:19:16.188913 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:16.197619 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3125,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.198009 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:16.379400 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.181s	user 0.112s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1416,"lbm_read_time_us":10697,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31757,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:16.379968 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:16.423010 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.043s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17613,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.423511 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:16.554435 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.131s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":549,"lbm_read_time_us":7862,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21320,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":69248,"update_count":2000}
I20260812 06:19:16.555096 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=11.118625
I20260812 06:19:16.595932 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.041s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16671,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:16.596386 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:16.616243 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5121,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.616806 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:16.626251 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.626734 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:16.790179 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.163s	user 0.085s	sys 0.067s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":151,"lbm_read_time_us":9094,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24590,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:16.790830 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:16.845273 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.054s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20195,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.845757 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:16.856009 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.856561 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:17.004333 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.148s	user 0.113s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1754,"lbm_read_time_us":10504,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26645,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:19:17.004881 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=11.118625
I20260812 06:19:17.049198 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.044s	user 0.015s	sys 0.025s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":21131,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:17.049693 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.060520 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.060997 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.073093 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4524,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.073486 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:17.210320 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.137s	user 0.100s	sys 0.033s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":782,"lbm_read_time_us":9472,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24919,"lbm_writes_lt_1ms":543,"mutex_wait_us":232,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:17.210937 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=11.118625
I20260812 06:19:17.246232 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.035s	user 0.026s	sys 0.006s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14610,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:17.246829 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.268476 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.268957 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.278470 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.279022 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:17.418396 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.139s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":54,"lbm_read_time_us":9221,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28009,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:17.418947 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=11.118625
I20260812 06:19:17.448593 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.029s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12401,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:17.449123 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.462488 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.463073 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:17.490588 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":35,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1178,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1386,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:17.491340 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling LogGCOp(052ab9e50ce54fa4886fa99144eb5000): free 124257190 bytes of WAL
I20260812 06:19:17.491580 26349 log_reader.cc:385] T 052ab9e50ce54fa4886fa99144eb5000: removed 12 log segments from log reader
I20260812 06:19:17.491640 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000014 (ops 67-71)
I20260812 06:19:17.491690 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000015 (ops 72-76)
I20260812 06:19:17.491727 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000016 (ops 77-81)
I20260812 06:19:17.491755 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000017 (ops 82-86)
I20260812 06:19:17.491781 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000018 (ops 87-91)
I20260812 06:19:17.491830 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000019 (ops 92-96)
I20260812 06:19:17.491864 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000020 (ops 97-100)
I20260812 06:19:17.491897 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000021 (ops 101-105)
I20260812 06:19:17.491928 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000022 (ops 106-110)
I20260812 06:19:17.491955 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000023 (ops 111-115)
I20260812 06:19:17.491983 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000024 (ops 116-120)
I20260812 06:19:17.492010 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000025 (ops 121-125)
I20260812 06:19:17.516623 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: LogGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:17.517107 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=3.181125
I20260812 06:19:17.529538 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.012s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:17.529991 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.539122 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3197,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.539608 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:17.707206 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.167s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877318,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":994,"lbm_read_time_us":10397,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34147,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:19:17.708025 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:17.752184 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.044s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17499,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.752683 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:17.762616 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.763144 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000): 471 bytes on disk
I20260812 06:19:17.763738 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:19:17.764400 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:17.897971 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.133s	user 0.110s	sys 0.022s 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":516,"lbm_read_time_us":10321,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24464,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:17.899441 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=12.110812
I20260812 06:19:17.931177 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.032s	user 0.020s	sys 0.009s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":13436,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:19:17.931792 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.196750
I20260812 06:19:17.942381 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3638,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:19:17.942826 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:18.092862 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.150s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":438,"cfile_cache_miss_bytes":20918395,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":526,"lbm_read_time_us":9846,"lbm_reads_lt_1ms":470,"lbm_write_time_us":23938,"lbm_writes_lt_1ms":449,"mutex_wait_us":261,"peak_mem_usage":50935538,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2030}
I20260812 06:19:18.093451 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:18.139173 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.046s	user 0.025s	sys 0.012s Metrics: {"bytes_written":16163762,"delete_count":0,"lbm_write_time_us":17220,"lbm_writes_lt_1ms":397,"reinsert_count":0,"update_count":1970}
I20260812 06:19:18.139664 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:18.156769 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.157284 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:18.336596 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.179s	user 0.124s	sys 0.044s Metrics: {"cfile_cache_miss":526,"cfile_cache_miss_bytes":24528548,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":11440,"lbm_reads_lt_1ms":566,"lbm_write_time_us":27684,"lbm_writes_lt_1ms":537,"mutex_wait_us":257,"peak_mem_usage":61829306,"reinsert_count":0,"spinlock_wait_cycles":29824,"update_count":2470}
I20260812 06:19:18.337116 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:18.386011 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.049s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21924,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.386575 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:18.398602 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.399178 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:18.559926 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.161s	user 0.125s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1211,"lbm_read_time_us":10974,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31124,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:18.560390 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:18.600466 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.040s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17716,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.600989 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:18.610814 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.611313 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:18.751406 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.140s	user 0.104s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":941,"lbm_read_time_us":9683,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29655,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:19:18.752184 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=11.118625
I20260812 06:19:18.796761 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19188,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:18.797220 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:18.807884 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.808408 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:18.821641 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4939,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.822204 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:18.855973 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushMRSOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1106,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2004,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:18.856587 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling LogGCOp(052ab9e50ce54fa4886fa99144eb5000): free 124710616 bytes of WAL
I20260812 06:19:18.856796 26349 log_reader.cc:385] T 052ab9e50ce54fa4886fa99144eb5000: removed 12 log segments from log reader
I20260812 06:19:18.856842 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000026 (ops 126-130)
I20260812 06:19:18.856870 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000027 (ops 131-135)
I20260812 06:19:18.856902 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000028 (ops 136-140)
I20260812 06:19:18.856935 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000029 (ops 141-145)
I20260812 06:19:18.856966 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000030 (ops 146-150)
I20260812 06:19:18.856998 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000031 (ops 151-155)
I20260812 06:19:18.857030 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000032 (ops 156-160)
I20260812 06:19:18.857061 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000033 (ops 161-165)
I20260812 06:19:18.857095 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000034 (ops 166-170)
I20260812 06:19:18.857127 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000035 (ops 171-175)
I20260812 06:19:18.857159 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000036 (ops 176-180)
I20260812 06:19:18.857190 26349 log.cc:1079] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/052ab9e50ce54fa4886fa99144eb5000/wal-000000037 (ops 181-185)
I20260812 06:19:18.881291 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: LogGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:18.881698 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000): 482 bytes on disk
I20260812 06:19:18.882143 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: UndoDeltaBlockGCOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.882690 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=3.181125
I20260812 06:19:18.893667 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:18.894047 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:18.909883 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.016s	user 0.004s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3252,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.910287 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:19.114980 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.205s	user 0.136s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":224,"lbm_read_time_us":14860,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36471,"lbm_writes_lt_1ms":743,"mutex_wait_us":24,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:19:19.116902 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=14.095187
I20260812 06:19:19.150378 26204 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.413s	user 1.627s	sys 0.117s
I20260812 06:19:19.166025 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.049s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23620,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.166579 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000): perf score=2.188937
I20260812 06:19:19.182161 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: FlushDeltaMemStoresOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.015s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.182886 26442 maintenance_manager.cc:419] P 5d0c7b34ce7e4d17985da64adba41b08: Scheduling MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000): perf score=1.000000
I20260812 06:19:19.203193 26204 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.002s	sys 0.000s
I20260812 06:19:19.203790 26204 tablet_server.cc:179] TabletServer@127.25.151.1:0 shutting down...
I20260812 06:19:19.316468 26349 maintenance_manager.cc:643] P 5d0c7b34ce7e4d17985da64adba41b08: MajorDeltaCompactionOp(052ab9e50ce54fa4886fa99144eb5000) complete. Timing: real 0.133s	user 0.073s	sys 0.060s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512298,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":249,"lbm_read_time_us":8302,"lbm_reads_lt_1ms":518,"lbm_write_time_us":21444,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:19:19.317148 26204 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:19.317556 26204 tablet_replica.cc:333] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08: stopping tablet replica
I20260812 06:19:19.317821 26204 raft_consensus.cc:2243] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:19.318058 26204 raft_consensus.cc:2272] T 052ab9e50ce54fa4886fa99144eb5000 P 5d0c7b34ce7e4d17985da64adba41b08 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:19.324827 26204 tablet_server.cc:196] TabletServer@127.25.151.1:0 shutdown complete.
I20260812 06:19:19.361758 26204 master.cc:562] Master@127.25.151.62:37167 shutting down...
I20260812 06:19:19.365201 26204 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:19.365365 26204 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:19.365444 26204 tablet_replica.cc:333] T 00000000000000000000000000000000 P 82060b7b5d674807b698266d43d798c6: stopping tablet replica
I20260812 06:19:19.377470 26204 master.cc:584] Master@127.25.151.62:37167 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4970 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:19.447197 26204 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.151.62:45805
I20260812 06:19:19.447540 26204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:19.449429 26485 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.449420 26490 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.449543 26486 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:19.449553 26204 server_base.cc:1061] running on GCE node
I20260812 06:19:19.449841 26204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:19.449882 26204 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:19.449900 26204 hybrid_clock.cc:648] HybridClock initialized: now 1786515559449900 us; error 0 us; skew 500 ppm
I20260812 06:19:19.450696 26204 webserver.cc:533] Webserver started at http://127.25.151.62:42899/ using document root <none> and password file <none>
I20260812 06:19:19.450852 26204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:19.450907 26204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:19.450981 26204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:19.451406 26204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/master-0-root/instance:
uuid: "4e57880af11d4aeba07a3667a6a8dd8f"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-jlzn"
I20260812 06:19:19.452853 26204 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:19.453663 26495 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.453881 26204 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:19.453949 26204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/master-0-root
uuid: "4e57880af11d4aeba07a3667a6a8dd8f"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-jlzn"
I20260812 06:19:19.454013 26204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:19.461349 26204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:19.461661 26204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:19.465416 26204 rpc_server.cc:307] RPC server started. Bound to: 127.25.151.62:45805
I20260812 06:19:19.476994 26572 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:19.477013 26571 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.151.62:45805 every 8 connection(s)
I20260812 06:19:19.478984 26572 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f: Bootstrap starting.
I20260812 06:19:19.479779 26572 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:19.480819 26572 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f: No bootstrap required, opened a new log
I20260812 06:19:19.481204 26572 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e57880af11d4aeba07a3667a6a8dd8f" member_type: VOTER }
I20260812 06:19:19.481288 26572 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:19.481319 26572 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4e57880af11d4aeba07a3667a6a8dd8f, State: Initialized, Role: FOLLOWER
I20260812 06:19:19.481459 26572 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [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: "4e57880af11d4aeba07a3667a6a8dd8f" member_type: VOTER }
I20260812 06:19:19.481529 26572 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:19.481575 26572 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:19.481624 26572 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:19.482283 26572 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e57880af11d4aeba07a3667a6a8dd8f" member_type: VOTER }
I20260812 06:19:19.482401 26572 leader_election.cc:304] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [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: 4e57880af11d4aeba07a3667a6a8dd8f; no voters: 
I20260812 06:19:19.482599 26572 leader_election.cc:290] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:19.482703 26575 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:19.482909 26575 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 1 LEADER]: Becoming Leader. State: Replica: 4e57880af11d4aeba07a3667a6a8dd8f, State: Running, Role: LEADER
I20260812 06:19:19.483016 26572 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:19.483037 26575 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [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: "4e57880af11d4aeba07a3667a6a8dd8f" member_type: VOTER }
I20260812 06:19:19.483434 26579 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4e57880af11d4aeba07a3667a6a8dd8f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e57880af11d4aeba07a3667a6a8dd8f" member_type: VOTER } }
I20260812 06:19:19.483534 26579 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:19.483449 26580 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4e57880af11d4aeba07a3667a6a8dd8f. Latest consensus state: current_term: 1 leader_uuid: "4e57880af11d4aeba07a3667a6a8dd8f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e57880af11d4aeba07a3667a6a8dd8f" member_type: VOTER } }
I20260812 06:19:19.483712 26580 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:19.483820 26582 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:19.484544 26582 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:19.484905 26204 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:19.486222 26582 catalog_manager.cc:1383] Generated new cluster ID: 15fcb1dd93bb488dab0a60c1644de456
I20260812 06:19:19.486279 26582 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:19.510748 26582 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:19.511296 26582 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:19.521684 26582 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f: Generated new TSK 0
I20260812 06:19:19.521840 26582 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:19.549414 26204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:19.551308 26605 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.551359 26603 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.551352 26602 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:19:19.551566 26204 server_base.cc:1061] running on GCE node
I20260812 06:19:19.551714 26204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:19.551752 26204 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:19.551772 26204 hybrid_clock.cc:648] HybridClock initialized: now 1786515559551772 us; error 0 us; skew 500 ppm
I20260812 06:19:19.552577 26204 webserver.cc:533] Webserver started at http://127.25.151.1:40439/ using document root <none> and password file <none>
I20260812 06:19:19.552740 26204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:19.552793 26204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:19.552866 26204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:19.553238 26204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/instance:
uuid: "c0f420410527449f9875c9a3535e37ed"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-jlzn"
I20260812 06:19:19.554634 26204 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:19.555492 26615 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.555742 26204 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:19.555828 26204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root
uuid: "c0f420410527449f9875c9a3535e37ed"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-jlzn"
I20260812 06:19:19.555894 26204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:19.570611 26204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:19.570909 26204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:19.571159 26204 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:19.571581 26204 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:19.571619 26204 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.571660 26204 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:19.571696 26204 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.575589 26204 rpc_server.cc:307] RPC server started. Bound to: 127.25.151.1:45935
I20260812 06:19:19.575637 26709 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.151.1:45935 every 8 connection(s)
I20260812 06:19:19.583361 26712 heartbeater.cc:344] Connected to a master server at 127.25.151.62:45805
I20260812 06:19:19.583456 26712 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:19.583657 26712 heartbeater.cc:507] Master 127.25.151.62:45805 requested a full tablet report, sending...
I20260812 06:19:19.584260 26518 ts_manager.cc:194] Registered new tserver with Master: c0f420410527449f9875c9a3535e37ed (127.25.151.1:45935)
I20260812 06:19:19.584794 26204 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008789002s
I20260812 06:19:19.585065 26518 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49978
I20260812 06:19:19.590871 26518 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49994:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:19.598589 26651 tablet_service.cc:1511] Processing CreateTablet for tablet cc7533cb39dd4b2c910d604fd9dc05c1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=17def151732541e39695976082a42499]), partition=
I20260812 06:19:19.598845 26651 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cc7533cb39dd4b2c910d604fd9dc05c1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:19.600838 26732 tablet_bootstrap.cc:492] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Bootstrap starting.
I20260812 06:19:19.601720 26732 tablet_bootstrap.cc:654] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:19.602632 26732 tablet_bootstrap.cc:492] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: No bootstrap required, opened a new log
I20260812 06:19:19.602701 26732 ts_tablet_manager.cc:1403] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:19.603034 26732 raft_consensus.cc:359] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c0f420410527449f9875c9a3535e37ed" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 45935 } }
I20260812 06:19:19.603111 26732 raft_consensus.cc:385] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:19.603132 26732 raft_consensus.cc:740] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c0f420410527449f9875c9a3535e37ed, State: Initialized, Role: FOLLOWER
I20260812 06:19:19.603237 26732 consensus_queue.cc:260] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [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: "c0f420410527449f9875c9a3535e37ed" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 45935 } }
I20260812 06:19:19.603296 26732 raft_consensus.cc:399] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:19.603323 26732 raft_consensus.cc:493] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:19.603355 26732 raft_consensus.cc:3060] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:19.604099 26732 raft_consensus.cc:515] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c0f420410527449f9875c9a3535e37ed" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 45935 } }
I20260812 06:19:19.604257 26732 leader_election.cc:304] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [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: c0f420410527449f9875c9a3535e37ed; no voters: 
I20260812 06:19:19.604450 26732 leader_election.cc:290] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:19.604568 26734 raft_consensus.cc:2804] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:19.604779 26734 raft_consensus.cc:697] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 1 LEADER]: Becoming Leader. State: Replica: c0f420410527449f9875c9a3535e37ed, State: Running, Role: LEADER
I20260812 06:19:19.604813 26732 ts_tablet_manager.cc:1434] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:19.604856 26712 heartbeater.cc:499] Master 127.25.151.62:45805 was elected leader, sending a full tablet report...
I20260812 06:19:19.604984 26734 consensus_queue.cc:237] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [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: "c0f420410527449f9875c9a3535e37ed" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 45935 } }
I20260812 06:19:19.606207 26518 catalog_manager.cc:5719] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed reported cstate change: term changed from 0 to 1, leader changed from <none> to c0f420410527449f9875c9a3535e37ed (127.25.151.1). New cstate: current_term: 1 leader_uuid: "c0f420410527449f9875c9a3535e37ed" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c0f420410527449f9875c9a3535e37ed" member_type: VOTER last_known_addr { host: "127.25.151.1" port: 45935 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:19.658771 26204 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.010s	sys 0.012s
I20260812 06:19:19.826633 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=23.023690
I20260812 06:19:19.977193 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.150s	user 0.118s	sys 0.029s Metrics: {"bytes_written":13210027,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":830,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38993,"lbm_writes_lt_1ms":879,"mutex_wait_us":200,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1610}
I20260812 06:19:19.977908 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): free 20743880 bytes of WAL
I20260812 06:19:19.978163 26624 log_reader.cc:385] T cc7533cb39dd4b2c910d604fd9dc05c1: removed 2 log segments from log reader
I20260812 06:19:19.978220 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000001 (ops 1-6)
I20260812 06:19:19.978252 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000002 (ops 7-11)
I20260812 06:19:19.982607 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {"spinlock_wait_cycles":12672}
I20260812 06:19:19.982985 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:19.993674 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3610359,"delete_count":0,"lbm_write_time_us":3380,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:19:19.994095 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:20.006698 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:20.007105 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:20.189980 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.183s	user 0.116s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815786,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":456,"lbm_read_time_us":13506,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25977,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":310,"threads_started":5,"update_count":2500}
I20260812 06:19:20.190511 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=14.095187
I20260812 06:19:20.232609 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.042s	user 0.030s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16188,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.233072 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:20.242362 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.242889 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:20.379616 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.137s	user 0.112s	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":46,"lbm_read_time_us":9220,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26823,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:20.380221 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): 20513813 bytes on disk
I20260812 06:19:20.380738 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:20.381299 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:20.410612 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.029s	user 0.016s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12362,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.411158 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:20.423446 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.423991 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:20.546511 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.122s	user 0.101s	sys 0.020s 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":525,"lbm_read_time_us":7000,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23485,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:19:20.547147 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:20.583636 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.036s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12516,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.584230 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:20.593920 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.594324 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:20.715222 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.121s	user 0.092s	sys 0.028s 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":1097,"lbm_read_time_us":7711,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22947,"lbm_writes_lt_1ms":443,"mutex_wait_us":458,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":2000}
I20260812 06:19:20.715677 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:20.763752 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.048s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":15988,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.764396 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:20.774515 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.775013 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:20.919349 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.144s	user 0.100s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":89,"lbm_read_time_us":9885,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21380,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.919984 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:20.954106 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.034s	user 0.026s	sys 0.001s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":12411,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.954599 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:20.964843 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.965328 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:21.077601 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.112s	user 0.096s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":7979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21020,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:19:21.078159 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:21.122469 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.044s	user 0.032s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18229,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.122920 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:21.132903 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3580,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.133517 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:21.161782 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1326,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1391,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:21.162470 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): free 121006440 bytes of WAL
I20260812 06:19:21.162724 26624 log_reader.cc:385] T cc7533cb39dd4b2c910d604fd9dc05c1: removed 12 log segments from log reader
I20260812 06:19:21.162774 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000003 (ops 12-16)
I20260812 06:19:21.162811 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000004 (ops 17-21)
I20260812 06:19:21.162844 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000005 (ops 22-26)
I20260812 06:19:21.162876 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000006 (ops 27-30)
I20260812 06:19:21.162907 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000007 (ops 31-35)
I20260812 06:19:21.162937 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000008 (ops 36-40)
I20260812 06:19:21.162968 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000009 (ops 41-45)
I20260812 06:19:21.162998 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000010 (ops 46-50)
I20260812 06:19:21.163028 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000011 (ops 51-55)
I20260812 06:19:21.163069 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000012 (ops 56-60)
I20260812 06:19:21.163098 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000013 (ops 61-65)
I20260812 06:19:21.163129 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000014 (ops 66-70)
I20260812 06:19:21.183338 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.021s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:19:21.183787 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): 472 bytes on disk
I20260812 06:19:21.184214 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) 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:19:21.184720 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=3.181125
I20260812 06:19:21.198544 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:21.198942 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:21.207585 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3130,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.207988 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:21.368265 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.160s	user 0.116s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1407,"lbm_read_time_us":10622,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30435,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:19:21.368863 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=14.095187
I20260812 06:19:21.420640 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.052s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22560,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.421207 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:21.439867 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.440343 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:21.584738 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.144s	user 0.128s	sys 0.015s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":8154,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27321,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:21.585278 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=14.095187
I20260812 06:19:21.626734 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.041s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18053,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.627619 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:21.771338 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.143s	user 0.107s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":556,"lbm_read_time_us":10389,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25621,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:19:21.771950 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:21.802814 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.031s	user 0.007s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.803339 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:21.822922 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.823439 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:21.941390 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.118s	user 0.082s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":7342,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21018,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:19:21.941835 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:21.970950 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.029s	user 0.017s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":11909,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.971427 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:21.986780 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.987228 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:22.110184 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.123s	user 0.100s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":728,"lbm_read_time_us":9385,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22493,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2000}
I20260812 06:19:22.110682 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:22.142980 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.032s	user 0.010s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12331,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.143510 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:22.153347 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.154034 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:22.269184 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.115s	user 0.103s	sys 0.011s 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":682,"lbm_read_time_us":7311,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22037,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:19:22.269659 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:22.316574 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.047s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12831,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.317180 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:22.327220 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.327739 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:22.473989 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.146s	user 0.097s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":576,"lbm_read_time_us":9800,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23606,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:19:22.474644 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:22.515537 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.041s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17246,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.516037 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:22.525802 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.526396 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:22.556833 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1174,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1961,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:22.557696 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): free 136275199 bytes of WAL
I20260812 06:19:22.557950 26624 log_reader.cc:385] T cc7533cb39dd4b2c910d604fd9dc05c1: removed 13 log segments from log reader
I20260812 06:19:22.558004 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000015 (ops 71-75)
I20260812 06:19:22.558051 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000016 (ops 76-80)
I20260812 06:19:22.558086 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000017 (ops 81-85)
I20260812 06:19:22.558120 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000018 (ops 86-90)
I20260812 06:19:22.558151 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000019 (ops 91-95)
I20260812 06:19:22.558182 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000020 (ops 96-100)
I20260812 06:19:22.558213 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000021 (ops 101-105)
I20260812 06:19:22.558244 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000022 (ops 106-110)
I20260812 06:19:22.558274 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000023 (ops 111-115)
I20260812 06:19:22.558305 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000024 (ops 116-120)
I20260812 06:19:22.558331 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000025 (ops 121-125)
I20260812 06:19:22.558355 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000026 (ops 126-130)
I20260812 06:19:22.558385 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000027 (ops 131-134)
I20260812 06:19:22.579241 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.021s	user 0.003s	sys 0.015s Metrics: {}
I20260812 06:19:22.579787 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): 482 bytes on disk
I20260812 06:19:22.580265 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.580879 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:22.594588 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.595029 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:22.616714 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.022s	user 0.004s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.617251 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:22.802716 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.185s	user 0.143s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":842,"lbm_read_time_us":13301,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31482,"lbm_writes_lt_1ms":643,"mutex_wait_us":300,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18048,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:19:22.803260 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=14.095187
I20260812 06:19:22.865326 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.062s	user 0.025s	sys 0.035s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25366,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.866050 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:22.881237 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.881628 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:23.049384 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.168s	user 0.108s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":9633,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29677,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":49536,"update_count":2500}
I20260812 06:19:23.049865 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=14.095187
I20260812 06:19:23.104678 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.055s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23574,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.105122 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:23.116024 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.116559 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:23.295747 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.179s	user 0.114s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":11956,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27327,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:19:23.296298 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=14.095187
I20260812 06:19:23.348358 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.052s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22387,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.348860 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:23.359467 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.359973 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:23.505255 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.145s	user 0.100s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":12272,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27634,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:19:23.505826 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:23.546089 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17472,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.546536 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:23.556314 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3698,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.556774 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:23.678292 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.121s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":680,"lbm_read_time_us":8427,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24340,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":2000}
I20260812 06:19:23.678788 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:23.721834 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.043s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16270,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.722369 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:23.733088 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.733867 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:23.852032 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.118s	user 0.089s	sys 0.028s 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":642,"lbm_read_time_us":8373,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23728,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.852680 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:23.899641 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.047s	user 0.012s	sys 0.031s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17274,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.900199 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:23.914690 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5510,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.915163 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:23.954718 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushMRSOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.039s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1208,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1444,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:23.955516 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): free 117302827 bytes of WAL
I20260812 06:19:23.955740 26624 log_reader.cc:385] T cc7533cb39dd4b2c910d604fd9dc05c1: removed 12 log segments from log reader
I20260812 06:19:23.955789 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000028 (ops 135-139)
I20260812 06:19:23.955852 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000029 (ops 140-144)
I20260812 06:19:23.955886 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000030 (ops 145-148)
I20260812 06:19:23.955915 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000031 (ops 149-153)
I20260812 06:19:23.955948 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000032 (ops 154-158)
I20260812 06:19:23.955974 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000033 (ops 159-162)
I20260812 06:19:23.956005 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000034 (ops 163-167)
I20260812 06:19:23.956037 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000035 (ops 168-172)
I20260812 06:19:23.956068 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000036 (ops 173-177)
I20260812 06:19:23.956100 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000037 (ops 178-182)
I20260812 06:19:23.956131 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000038 (ops 183-187)
I20260812 06:19:23.956163 26624 log.cc:1079] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: Deleting log segment in path: /tmp/dist-test-taskElgz3w/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515554467042-26204-0/minicluster-data/ts-0-root/wals/cc7533cb39dd4b2c910d604fd9dc05c1/wal-000000039 (ops 188-192)
I20260812 06:19:23.976416 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: LogGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.021s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:19:23.976818 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:23.999178 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.022s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.999606 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1): 462 bytes on disk
I20260812 06:19:24.000008 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: UndoDeltaBlockGCOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.000530 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=2.188937
I20260812 06:19:24.010358 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.010927 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:24.142395 26204 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.484s	user 1.694s	sys 0.105s
I20260812 06:19:24.204718 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.194s	user 0.134s	sys 0.058s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918337,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14763,"lbm_reads_lt_1ms":670,"lbm_write_time_us":32906,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:19:24.205199 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=10.126437
I20260812 06:19:24.229286 26204 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.001s	sys 0.000s
I20260812 06:19:24.230594 26204 tablet_server.cc:179] TabletServer@127.25.151.1:0 shutting down...
I20260812 06:19:24.233155 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: FlushDeltaMemStoresOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11606,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:24.233737 26713 maintenance_manager.cc:419] P c0f420410527449f9875c9a3535e37ed: Scheduling MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1): perf score=1.000000
I20260812 06:19:24.324987 26624 maintenance_manager.cc:643] P c0f420410527449f9875c9a3535e37ed: MajorDeltaCompactionOp(cc7533cb39dd4b2c910d604fd9dc05c1) complete. Timing: real 0.091s	user 0.067s	sys 0.024s 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":370,"lbm_read_time_us":7027,"lbm_reads_lt_1ms":367,"lbm_write_time_us":15932,"lbm_writes_lt_1ms":343,"mutex_wait_us":59,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:24.325945 26204 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:24.326167 26204 tablet_replica.cc:333] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed: stopping tablet replica
I20260812 06:19:24.326330 26204 raft_consensus.cc:2243] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:24.326484 26204 raft_consensus.cc:2272] T cc7533cb39dd4b2c910d604fd9dc05c1 P c0f420410527449f9875c9a3535e37ed [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:24.330509 26204 tablet_server.cc:196] TabletServer@127.25.151.1:0 shutdown complete.
I20260812 06:19:24.355683 26204 master.cc:562] Master@127.25.151.62:45805 shutting down...
I20260812 06:19:24.358705 26204 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:24.358908 26204 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:24.358980 26204 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4e57880af11d4aeba07a3667a6a8dd8f: stopping tablet replica
I20260812 06:19:24.371230 26204 master.cc:584] Master@127.25.151.62:45805 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4993 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9965 ms total)

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