[==========] Running 1 test from 1 test suite.
[----------] Global test environment set-up.
[----------] 1 test from UpdateScanDeltaCompactionTest
[ RUN      ] UpdateScanDeltaCompactionTest.TestAll
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:36:03.658313 11584 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.80.62:33305
I20260812 06:36:03.659530 11584 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:36:03.660215 11584 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:36:03.666659 11590 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:36:03.668036 11584 server_base.cc:1061] running on GCE node
W20260812 06:36:03.668383 11593 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:36:03.668426 11596 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:36:03.668841 11584 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:36:03.668983 11584 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:36:03.669027 11584 hybrid_clock.cc:648] HybridClock initialized: now 1786516563669025 us; error 0 us; skew 500 ppm
I20260812 06:36:03.670796 11584 webserver.cc:533] Webserver started at http://127.11.80.62:33283/ using document root <none> and password file <none>
I20260812 06:36:03.671329 11584 fs_manager.cc:362] Metadata directory not provided
I20260812 06:36:03.671392 11584 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:36:03.671618 11584 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:36:03.673375 11584 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/master-0-root/instance:
uuid: "af411fb8b0654e64b16a87975c8a12c5"
format_stamp: "Formatted at 2026-08-12 06:36:03 on dist-test-slave-1vmg"
I20260812 06:36:03.676608 11584 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:36:03.678442 11601 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:36:03.679348 11584 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:36:03.679446 11584 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/master-0-root
uuid: "af411fb8b0654e64b16a87975c8a12c5"
format_stamp: "Formatted at 2026-08-12 06:36:03 on dist-test-slave-1vmg"
I20260812 06:36:03.679523 11584 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-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:36:03.694825 11584 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:36:03.695448 11584 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:36:03.695595 11584 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:36:03.703464 11584 rpc_server.cc:307] RPC server started. Bound to: 127.11.80.62:33305
I20260812 06:36:03.703462 11679 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.80.62:33305 every 8 connection(s)
I20260812 06:36:03.705667 11680 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:36:03.710904 11680 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: Bootstrap starting.
I20260812 06:36:03.713249 11680 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: Neither blocks nor log segments found. Creating new log.
I20260812 06:36:03.713872 11680 log.cc:826] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:36:03.715232 11680 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: No bootstrap required, opened a new log
I20260812 06:36:03.718127 11680 raft_consensus.cc:359] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af411fb8b0654e64b16a87975c8a12c5" member_type: VOTER }
I20260812 06:36:03.718291 11680 raft_consensus.cc:385] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:36:03.718359 11680 raft_consensus.cc:740] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af411fb8b0654e64b16a87975c8a12c5, State: Initialized, Role: FOLLOWER
I20260812 06:36:03.719012 11680 consensus_queue.cc:260] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [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: "af411fb8b0654e64b16a87975c8a12c5" member_type: VOTER }
I20260812 06:36:03.719220 11680 raft_consensus.cc:399] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:36:03.719290 11680 raft_consensus.cc:493] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:36:03.719445 11680 raft_consensus.cc:3060] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:36:03.720129 11680 raft_consensus.cc:515] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af411fb8b0654e64b16a87975c8a12c5" member_type: VOTER }
I20260812 06:36:03.720562 11680 leader_election.cc:304] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [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: af411fb8b0654e64b16a87975c8a12c5; no voters: 
I20260812 06:36:03.720891 11680 leader_election.cc:290] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:36:03.721005 11683 raft_consensus.cc:2804] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:36:03.721222 11683 raft_consensus.cc:697] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 1 LEADER]: Becoming Leader. State: Replica: af411fb8b0654e64b16a87975c8a12c5, State: Running, Role: LEADER
I20260812 06:36:03.721568 11683 consensus_queue.cc:237] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [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: "af411fb8b0654e64b16a87975c8a12c5" member_type: VOTER }
I20260812 06:36:03.721777 11680 sys_catalog.cc:565] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:36:03.723407 11685 sys_catalog.cc:455] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader af411fb8b0654e64b16a87975c8a12c5. Latest consensus state: current_term: 1 leader_uuid: "af411fb8b0654e64b16a87975c8a12c5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af411fb8b0654e64b16a87975c8a12c5" member_type: VOTER } }
I20260812 06:36:03.723527 11685 sys_catalog.cc:458] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:36:03.723798 11684 sys_catalog.cc:455] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "af411fb8b0654e64b16a87975c8a12c5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af411fb8b0654e64b16a87975c8a12c5" member_type: VOTER } }
I20260812 06:36:03.723878 11684 sys_catalog.cc:458] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:36:03.724144 11584 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:36:03.726493 11707 catalog_manager.cc:1594] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:36:03.726552 11707 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:36:03.726619 11703 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:36:03.727440 11703 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:36:03.731779 11703 catalog_manager.cc:1383] Generated new cluster ID: 76e8ffe584044f1da248730971254cd1
I20260812 06:36:03.731827 11703 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:36:03.743039 11703 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:36:03.744050 11703 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:36:03.756031 11703 catalog_manager.cc:6092] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: Generated new TSK 0
I20260812 06:36:03.756515 11703 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:36:03.788695 11584 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:36:03.791400 11714 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:36:03.791298 11716 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:36:03.791518 11584 server_base.cc:1061] running on GCE node
W20260812 06:36:03.791296 11712 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:36:03.791867 11584 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:36:03.791923 11584 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:36:03.791944 11584 hybrid_clock.cc:648] HybridClock initialized: now 1786516563791944 us; error 0 us; skew 500 ppm
I20260812 06:36:03.792899 11584 webserver.cc:533] Webserver started at http://127.11.80.1:43947/ using document root <none> and password file <none>
I20260812 06:36:03.793061 11584 fs_manager.cc:362] Metadata directory not provided
I20260812 06:36:03.793128 11584 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:36:03.793201 11584 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:36:03.793622 11584 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/ts-0-root/instance:
uuid: "0ad813103238463fb17e46a8f942f3b6"
format_stamp: "Formatted at 2026-08-12 06:36:03 on dist-test-slave-1vmg"
I20260812 06:36:03.795389 11584 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:36:03.796391 11721 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:36:03.796650 11584 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:36:03.796726 11584 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/ts-0-root
uuid: "0ad813103238463fb17e46a8f942f3b6"
format_stamp: "Formatted at 2026-08-12 06:36:03 on dist-test-slave-1vmg"
I20260812 06:36:03.796790 11584 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-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:36:03.808357 11584 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:36:03.808840 11584 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:36:03.809340 11584 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:36:03.810186 11584 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:36:03.810250 11584 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:36:03.810304 11584 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:36:03.810334 11584 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:36:03.820611 11584 rpc_server.cc:307] RPC server started. Bound to: 127.11.80.1:45023
I20260812 06:36:03.820631 11827 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.80.1:45023 every 8 connection(s)
I20260812 06:36:03.830161 11828 heartbeater.cc:344] Connected to a master server at 127.11.80.62:33305
I20260812 06:36:03.830376 11828 heartbeater.cc:461] Registering TS with master...
I20260812 06:36:03.830808 11828 heartbeater.cc:507] Master 127.11.80.62:33305 requested a full tablet report, sending...
I20260812 06:36:03.832230 11626 ts_manager.cc:194] Registered new tserver with Master: 0ad813103238463fb17e46a8f942f3b6 (127.11.80.1:45023)
I20260812 06:36:03.832679 11584 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011179217s
I20260812 06:36:03.833567 11626 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49580
I20260812 06:36:03.841615 11626 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49596:
name: "update-scan-delta-compact-tbl"
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: "string"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "int64"
    type: INT64
    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 {
    columns {
      name: "key"
    }
  }
}
I20260812 06:36:03.856681 11766 tablet_service.cc:1511] Processing CreateTablet for tablet 60ab298c91334b429b0400ade230cc6f (DEFAULT_TABLE table=update-scan-delta-compact-tbl [id=c34c951a66064b8bab8c602f5bce0bf3]), partition=RANGE (key) PARTITION UNBOUNDED
I20260812 06:36:03.857112 11766 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 60ab298c91334b429b0400ade230cc6f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:36:03.863148 11845 tablet_bootstrap.cc:492] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: Bootstrap starting.
I20260812 06:36:03.864444 11845 tablet_bootstrap.cc:654] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: Neither blocks nor log segments found. Creating new log.
I20260812 06:36:03.865442 11845 tablet_bootstrap.cc:492] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: No bootstrap required, opened a new log
I20260812 06:36:03.865525 11845 ts_tablet_manager.cc:1403] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:36:03.865936 11845 raft_consensus.cc:359] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ad813103238463fb17e46a8f942f3b6" member_type: VOTER last_known_addr { host: "127.11.80.1" port: 45023 } }
I20260812 06:36:03.866034 11845 raft_consensus.cc:385] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:36:03.866055 11845 raft_consensus.cc:740] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0ad813103238463fb17e46a8f942f3b6, State: Initialized, Role: FOLLOWER
I20260812 06:36:03.866180 11845 consensus_queue.cc:260] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [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: "0ad813103238463fb17e46a8f942f3b6" member_type: VOTER last_known_addr { host: "127.11.80.1" port: 45023 } }
I20260812 06:36:03.866252 11845 raft_consensus.cc:399] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:36:03.866292 11845 raft_consensus.cc:493] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:36:03.866343 11845 raft_consensus.cc:3060] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:36:03.867117 11845 raft_consensus.cc:515] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ad813103238463fb17e46a8f942f3b6" member_type: VOTER last_known_addr { host: "127.11.80.1" port: 45023 } }
I20260812 06:36:03.867245 11845 leader_election.cc:304] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [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: 0ad813103238463fb17e46a8f942f3b6; no voters: 
I20260812 06:36:03.867427 11845 leader_election.cc:290] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:36:03.867720 11849 raft_consensus.cc:2804] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:36:03.867784 11845 ts_tablet_manager.cc:1434] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:36:03.867951 11828 heartbeater.cc:499] Master 127.11.80.62:33305 was elected leader, sending a full tablet report...
I20260812 06:36:03.867982 11849 raft_consensus.cc:697] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 1 LEADER]: Becoming Leader. State: Replica: 0ad813103238463fb17e46a8f942f3b6, State: Running, Role: LEADER
I20260812 06:36:03.868150 11849 consensus_queue.cc:237] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [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: "0ad813103238463fb17e46a8f942f3b6" member_type: VOTER last_known_addr { host: "127.11.80.1" port: 45023 } }
I20260812 06:36:03.870736 11626 catalog_manager.cc:5719] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0ad813103238463fb17e46a8f942f3b6 (127.11.80.1). New cstate: current_term: 1 leader_uuid: "0ad813103238463fb17e46a8f942f3b6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0ad813103238463fb17e46a8f942f3b6" member_type: VOTER last_known_addr { host: "127.11.80.1" port: 45023 } health_report { overall_health: HEALTHY } } }
I20260812 06:36:07.822208 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=8.827903
I20260812 06:36:09.682782 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 1.860s	user 1.824s	sys 0.012s Metrics: {"bytes_written":328688,"cfile_init":1,"compiler_manager_pool.queue_time_us":206,"compiler_manager_pool.run_cpu_time_us":197053,"compiler_manager_pool.run_wall_time_us":199184,"dirs.queue_time_us":210,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":945,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":7185,"lbm_writes_lt_1ms":155,"peak_mem_usage":0,"rows_written":119001,"spinlock_wait_cycles":1280,"thread_start_us":207,"threads_started":2}
I20260812 06:36:09.684146 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f): 796873 bytes on disk
I20260812 06:36:09.684878 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:36:11.685599 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=4.859153
I20260812 06:36:12.921638 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 1.236s	user 1.224s	sys 0.008s Metrics: {"bytes_written":245560,"cfile_init":1,"dirs.queue_time_us":193,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1025,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":5597,"lbm_writes_lt_1ms":123,"peak_mem_usage":0,"rows_written":91000,"thread_start_us":88,"threads_started":1}
I20260812 06:36:12.922528 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f): perf score=0.014469
I20260812 06:36:15.120491 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 2.198s	user 2.189s	sys 0.004s Metrics: {"bytes_written":577985,"cfile_cache_hit":10,"cfile_cache_hit_bytes":2509,"cfile_cache_miss":246,"cfile_cache_miss_bytes":2933167,"cfile_init":6,"delta_iterators_relevant":4,"dirs.queue_time_us":176,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1342,"drs_written":1,"lbm_read_time_us":5688,"lbm_reads_lt_1ms":270,"lbm_write_time_us":10621,"lbm_writes_lt_1ms":261,"num_input_rowsets":2,"peak_mem_usage":1902383,"rows_written":210001,"thread_start_us":83,"threads_started":1}
I20260812 06:36:15.121194 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f): 1408672 bytes on disk
I20260812 06:36:15.121636 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f) 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:36:15.122048 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=3.866965
I20260812 06:36:16.485080 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 1.363s	user 1.346s	sys 0.004s Metrics: {"bytes_written":231981,"cfile_init":1,"dirs.queue_time_us":340,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":823,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":5663,"lbm_writes_lt_1ms":118,"peak_mem_usage":0,"rows_written":86000,"thread_start_us":74,"threads_started":1}
I20260812 06:36:16.485772 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f): perf score=0.014250
I20260812 06:36:19.470693 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 2.985s	user 2.960s	sys 0.024s Metrics: {"bytes_written":817251,"cfile_cache_hit":10,"cfile_cache_hit_bytes":3478,"cfile_cache_miss":348,"cfile_cache_miss_bytes":4148522,"cfile_init":6,"delta_iterators_relevant":4,"dirs.queue_time_us":632,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":8346,"lbm_reads_lt_1ms":372,"lbm_write_time_us":15276,"lbm_writes_lt_1ms":362,"num_input_rowsets":2,"peak_mem_usage":3381033,"rows_written":296001,"thread_start_us":454,"threads_started":6}
I20260812 06:36:19.471423 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=6.843528
I20260812 06:36:20.853947 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 1.382s	user 1.361s	sys 0.008s Metrics: {"bytes_written":282365,"cfile_init":1,"dirs.queue_time_us":200,"dirs.run_cpu_time_us":155,"dirs.run_wall_time_us":843,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":6304,"lbm_writes_lt_1ms":140,"peak_mem_usage":0,"rows_written":105000,"thread_start_us":98,"threads_started":1}
I20260812 06:36:20.854657 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f): 2692079 bytes on disk
I20260812 06:36:20.855315 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":2,"lbm_read_time_us":115,"lbm_reads_lt_1ms":8}
I20260812 06:36:20.855847 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f): perf score=0.013983
I20260812 06:36:24.995494 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 4.139s	user 4.118s	sys 0.008s Metrics: {"bytes_written":1104489,"cfile_cache_hit":10,"cfile_cache_hit_bytes":4559,"cfile_cache_miss":470,"cfile_cache_miss_bytes":5630289,"cfile_init":5,"delta_iterators_relevant":4,"dirs.queue_time_us":755,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":10836,"lbm_reads_lt_1ms":490,"lbm_write_time_us":20599,"lbm_writes_lt_1ms":483,"mutex_wait_us":36,"num_input_rowsets":2,"peak_mem_usage":4778435,"rows_written":401001,"spinlock_wait_cycles":4096,"thread_start_us":410,"threads_started":7}
I20260812 06:36:24.996105 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f): 2695130 bytes on disk
I20260812 06:36:24.996485 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4}
I20260812 06:36:24.996898 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=12.796653
I20260812 06:36:27.137652 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 2.141s	user 2.129s	sys 0.008s Metrics: {"bytes_written":396583,"cfile_init":1,"dirs.queue_time_us":205,"dirs.run_cpu_time_us":139,"dirs.run_wall_time_us":691,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":9691,"lbm_writes_lt_1ms":190,"peak_mem_usage":0,"rows_written":148000,"thread_start_us":118,"threads_started":1}
I20260812 06:36:27.138203 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f): perf score=0.013608
I20260812 06:36:33.165834 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 6.027s	user 5.974s	sys 0.040s Metrics: {"bytes_written":1513342,"cfile_cache_hit":10,"cfile_cache_hit_bytes":6240,"cfile_cache_miss":640,"cfile_cache_miss_bytes":7715274,"cfile_init":6,"delta_iterators_relevant":4,"dirs.queue_time_us":694,"dirs.run_cpu_time_us":161,"dirs.run_wall_time_us":867,"drs_written":1,"lbm_read_time_us":15565,"lbm_reads_lt_1ms":664,"lbm_write_time_us":28579,"lbm_writes_lt_1ms":654,"num_input_rowsets":2,"peak_mem_usage":6484568,"rows_written":549001,"thread_start_us":438,"threads_started":7}
I20260812 06:36:33.166431 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=22.718528
I20260812 06:36:36.447733 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 3.281s	user 3.260s	sys 0.016s Metrics: {"bytes_written":596874,"cfile_init":1,"dirs.queue_time_us":188,"dirs.run_cpu_time_us":163,"dirs.run_wall_time_us":885,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":13414,"lbm_writes_lt_1ms":276,"peak_mem_usage":0,"rows_written":223000,"thread_start_us":94,"threads_started":1}
I20260812 06:36:36.448328 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=3.866965
I20260812 06:36:37.569197 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 1.121s	user 1.095s	sys 0.008s Metrics: {"bytes_written":214002,"cfile_init":1,"dirs.queue_time_us":174,"dirs.run_cpu_time_us":164,"dirs.run_wall_time_us":956,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":111,"peak_mem_usage":0,"rows_written":80000,"thread_start_us":72,"threads_started":1}
I20260812 06:36:37.569944 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f): perf score=0.021842
I20260812 06:36:41.955235 11584 update_scan_delta_compact-test.cc:209] Time spent Insert: real 38.078s	user 36.037s	sys 1.691s
I20260812 06:36:41.957406 11914 scanners.cc:360] slow scan reporting is disabled: set --show_slow_scans to enable
I20260812 06:36:43.214213 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.257s	user 0.071s	sys 0.000s
I20260812 06:36:43.244462 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1002, attempt_no=0}) took 1253 ms. Trace:
I20260812 06:36:43.244572 11856 rpcz_store.cc:276] 0812 06:36:41.991297 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:41.991348 (+    51us) service_pool.cc:224] Handling call
0812 06:36:43.244449 (+1253101us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:41.991731 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:41.991819 (+    88us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:41.991823 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:41.991824 (+     1us) tablet.cc:662] Decoding operations
0812 06:36:41.995355 (+  3531us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:41.995364 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:41.995368 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:41.999965 (+  4597us) tablet.cc:701] Row locks acquired
0812 06:36:41.999968 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:36:42.000006 (+    38us) write_op.cc:270] Start()
0812 06:36:42.000030 (+    24us) write_op.cc:276] Timestamp: P: 1786516601999996 usec, L: 0
0812 06:36:42.000033 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:42.000176 (+   143us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:42.000608 (+   432us) op_driver.cc:464] REPLICATION: finished
0812 06:36:42.000678 (+    70us) write_op.cc:301] APPLY: starting
0812 06:36:42.000689 (+    11us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:42.614004 (+613315us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:42.614019 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:43.242364 (+628345us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:43.242780 (+   416us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:43.242786 (+     6us) write_op.cc:312] APPLY: finished
0812 06:36:43.243852 (+  1066us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:43.244050 (+   198us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:43.244316 (+   266us) write_op.cc:454] Released schema lock
0812 06:36:43.244365 (+    49us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":41,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18418000,"num_ops":1000,"prepare.queue_time_us":47,"prepare.run_cpu_time_us":8462,"prepare.run_wall_time_us":8500,"replication_time_us":556,"spinlock_wait_cycles":1037440,"thread_start_us":85,"threads_started":1,"wal-append.queue_time_us":183}]]}
I20260812 06:36:44.429273 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1003, attempt_no=0}) took 1178 ms. Trace:
I20260812 06:36:44.429472 11856 rpcz_store.cc:276] 0812 06:36:43.250749 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:43.250791 (+    42us) service_pool.cc:224] Handling call
0812 06:36:44.429255 (+1178464us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:43.263028 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:43.263119 (+    91us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:43.263122 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:36:43.263124 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:43.266711 (+  3587us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:43.266720 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:43.266724 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:43.271539 (+  4815us) tablet.cc:701] Row locks acquired
0812 06:36:43.271541 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:43.271597 (+    56us) write_op.cc:270] Start()
0812 06:36:43.271623 (+    26us) write_op.cc:276] Timestamp: P: 1786516603271585 usec, L: 0
0812 06:36:43.271625 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:43.271797 (+   172us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:43.282172 (+ 10375us) op_driver.cc:464] REPLICATION: finished
0812 06:36:43.282235 (+    63us) write_op.cc:301] APPLY: starting
0812 06:36:43.282246 (+    11us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:43.850846 (+568600us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:43.850862 (+    16us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:44.427236 (+576374us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:44.427662 (+   426us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:44.427668 (+     6us) write_op.cc:312] APPLY: finished
0812 06:36:44.428678 (+  1010us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:44.428862 (+   184us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:44.429106 (+   244us) write_op.cc:454] Released schema lock
0812 06:36:44.429162 (+    56us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":31,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18426212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":565,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":11883,"prepare.run_cpu_time_us":8845,"prepare.run_wall_time_us":19088,"replication_time_us":10528,"spinlock_wait_cycles":1381760,"thread_start_us":168,"threads_started":2}]]}
I20260812 06:36:44.513190 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.299s	user 0.066s	sys 0.004s
I20260812 06:36:45.563654 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1004, attempt_no=0}) took 1124 ms. Trace:
I20260812 06:36:45.563752 11856 rpcz_store.cc:276] 0812 06:36:44.438861 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:44.438902 (+    41us) service_pool.cc:224] Handling call
0812 06:36:45.563638 (+1124736us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:44.467643 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:44.467760 (+   117us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:44.467765 (+     5us) write_op.cc:435] Acquired schema lock
0812 06:36:44.467767 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:44.471467 (+  3700us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:44.471479 (+    12us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:44.471483 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:44.476334 (+  4851us) tablet.cc:701] Row locks acquired
0812 06:36:44.476336 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:44.476394 (+    58us) write_op.cc:270] Start()
0812 06:36:44.476425 (+    31us) write_op.cc:276] Timestamp: P: 1786516604476381 usec, L: 0
0812 06:36:44.476428 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:44.476640 (+   212us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:44.477309 (+   669us) op_driver.cc:464] REPLICATION: finished
0812 06:36:44.477396 (+    87us) write_op.cc:301] APPLY: starting
0812 06:36:44.477412 (+    16us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:45.043978 (+566566us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:45.043993 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:45.561996 (+518003us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:45.562295 (+   299us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:45.562300 (+     5us) write_op.cc:312] APPLY: finished
0812 06:36:45.563086 (+   786us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:45.563277 (+   191us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:45.563496 (+   219us) write_op.cc:454] Released schema lock
0812 06:36:45.563543 (+    47us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":43,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18418000,"num_ops":1000,"prepare.queue_time_us":8317,"prepare.run_cpu_time_us":8429,"prepare.run_wall_time_us":9064,"replication_time_us":856,"spinlock_wait_cycles":1402880,"thread_start_us":167,"threads_started":2}]]}
I20260812 06:36:45.599874 11752 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Scan from 127.0.0.1:34730 (request call id 1103) took 1085 ms. Trace:
I20260812 06:36:45.600071 11752 rpcz_store.cc:276] 0812 06:36:44.514049 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:44.514097 (+    48us) service_pool.cc:224] Handling call
0812 06:36:44.514210 (+   113us) tablet_service.cc:2890] Created scanner 68cf9a18aeeb485ebcbc65045912351c for tablet 60ab298c91334b429b0400ade230cc6f, query id is ac2ff492bd4040af944fa52563fbffa6
0812 06:36:44.514397 (+   187us) tablet_service.cc:3030] Creating iterator
0812 06:36:44.514416 (+    19us) tablet_service.cc:3408] Waiting safe time to advance
0812 06:36:44.514425 (+     9us) tablet_service.cc:3415] Waiting for operations to commit
0812 06:36:45.563301 (+1048876us) tablet_service.cc:3431] All operations in snapshot committed. Waited for 1048872 microseconds
0812 06:36:45.563395 (+    94us) tablet_service.cc:3055] Iterator created
0812 06:36:45.569399 (+  6004us) tablet_service.cc:3077] Iterator init: OK
0812 06:36:45.569430 (+    31us) tablet_service.cc:3120] has_more: true
0812 06:36:45.569463 (+    33us) tablet_service.cc:3137] Continuing scan request
0812 06:36:45.569505 (+    42us) tablet_service.cc:3201] Found scanner 68cf9a18aeeb485ebcbc65045912351c for tablet 60ab298c91334b429b0400ade230cc6f, query id is ac2ff492bd4040af944fa52563fbffa6
0812 06:36:45.599861 (+ 30356us) inbound_call.cc:177] Queueing success response
Metrics: {"cfile_cache_hit":7,"cfile_cache_hit_bytes":11509,"rowset_iterators":4,"scanner_bytes_read":10845}
W20260812 06:36:45.601401 11912 scanner-internal.cc:458] Time spent opening tablet: real 1.088s	user 0.001s	sys 0.000s
I20260812 06:36:46.666133 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1005, attempt_no=0}) took 1092 ms. Trace:
I20260812 06:36:46.666251 11856 rpcz_store.cc:276] 0812 06:36:45.573538 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:45.573585 (+    47us) service_pool.cc:224] Handling call
0812 06:36:46.666118 (+1092533us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:45.587033 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:45.587148 (+   115us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:45.587152 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:45.587154 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:45.590617 (+  3463us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:45.590628 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:45.590632 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:45.595221 (+  4589us) tablet.cc:701] Row locks acquired
0812 06:36:45.595223 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:45.595277 (+    54us) write_op.cc:270] Start()
0812 06:36:45.595307 (+    30us) write_op.cc:276] Timestamp: P: 1786516605595264 usec, L: 0
0812 06:36:45.595310 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:45.595508 (+   198us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:45.603739 (+  8231us) op_driver.cc:464] REPLICATION: finished
0812 06:36:45.603885 (+   146us) write_op.cc:301] APPLY: starting
0812 06:36:45.603899 (+    14us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:46.177497 (+573598us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:46.177512 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:46.664618 (+487106us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:46.664912 (+   294us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:46.664916 (+     4us) write_op.cc:312] APPLY: finished
0812 06:36:46.665597 (+   681us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:46.665757 (+   160us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:46.665988 (+   231us) write_op.cc:454] Released schema lock
0812 06:36:46.666037 (+    49us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":33,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18426212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":34,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":13088,"prepare.run_cpu_time_us":8543,"prepare.run_wall_time_us":8543,"replication_time_us":8409,"spinlock_wait_cycles":1234048,"thread_start_us":145,"threads_started":2}]]}
I20260812 06:36:46.780138 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 2.267s	user 0.066s	sys 0.000s
W20260812 06:36:48.436902 11727 tablet_replica.cc:1406] Time spent applying in-flights took a long time: real 0.483s	user 0.003s	sys 0.000s
I20260812 06:36:48.437260 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1006, attempt_no=0}) took 1765 ms. Trace:
I20260812 06:36:48.437328 11856 rpcz_store.cc:276] 0812 06:36:46.672247 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:46.672293 (+    46us) service_pool.cc:224] Handling call
0812 06:36:48.437248 (+1764955us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:46.672770 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:46.672874 (+   104us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:46.672878 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:46.672880 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:46.682459 (+  9579us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:46.682469 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:46.682473 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:46.686801 (+  4328us) tablet.cc:701] Row locks acquired
0812 06:36:46.686804 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:36:46.686852 (+    48us) write_op.cc:270] Start()
0812 06:36:46.686879 (+    27us) write_op.cc:276] Timestamp: P: 1786516606686841 usec, L: 0
0812 06:36:46.686881 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:46.687135 (+   254us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:46.695060 (+  7925us) op_driver.cc:464] REPLICATION: finished
0812 06:36:46.695174 (+   114us) write_op.cc:301] APPLY: starting
0812 06:36:46.695187 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:47.272783 (+577596us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:47.272798 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:48.435269 (+1162471us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:48.435583 (+   314us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=3000,key_file_lookups=3000,delta_file_lookups=454,mrs_lookups=0
0812 06:36:48.435587 (+     4us) write_op.cc:312] APPLY: finished
0812 06:36:48.436627 (+  1040us) log.cc:844] Serialized 14020 byte log entry
0812 06:36:48.436884 (+   257us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:48.437118 (+   234us) write_op.cc:454] Released schema lock
0812 06:36:48.437165 (+    47us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":27,"cfile_cache_hit":5998,"cfile_cache_hit_bytes":27781627,"cfile_cache_miss":4,"cfile_cache_miss_bytes":22459,"cfile_init":2,"lbm_read_time_us":169,"lbm_reads_lt_1ms":12,"num_ops":1000,"prepare.queue_time_us":168,"prepare.run_cpu_time_us":8443,"prepare.run_wall_time_us":14431,"replication_time_us":8155,"spinlock_wait_cycles":1098880,"thread_start_us":171,"threads_started":2,"wal-append.queue_time_us":180}]]}
I20260812 06:36:48.439332 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 10.869s	user 9.813s	sys 0.044s Metrics: {"bytes_written":35284,"cfile_cache_hit":104,"cfile_cache_hit_bytes":328668,"cfile_cache_miss":900,"cfile_cache_miss_bytes":11635696,"cfile_init":10,"delete_count":0,"delta_iterators_relevant":6,"dirs.queue_time_us":1067,"dirs.run_cpu_time_us":66,"dirs.run_wall_time_us":67,"drs_written":1,"lbm_read_time_us":23655,"lbm_reads_lt_1ms":940,"lbm_write_time_us":51140,"lbm_writes_lt_1ms":1016,"num_input_rowsets":3,"peak_mem_usage":8925378,"reinsert_count":0,"rows_written":852001,"thread_start_us":102,"threads_started":1,"update_count":9094}
I20260812 06:36:48.441960 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling FlushMRSOp(60ab298c91334b429b0400ade230cc6f): perf score=12.796653
I20260812 06:36:48.492559 11752 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Scan from 127.0.0.1:34730 (request call id 1154) took 1711 ms. Trace:
I20260812 06:36:48.492746 11752 rpcz_store.cc:276] 0812 06:36:46.780974 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:46.781012 (+    38us) service_pool.cc:224] Handling call
0812 06:36:46.781125 (+   113us) tablet_service.cc:2890] Created scanner c4e018fa6f0349a68a775a6c4b818b1a for tablet 60ab298c91334b429b0400ade230cc6f, query id is 98b295c57d9c4ead9aee129af28d881f
0812 06:36:46.781334 (+   209us) tablet_service.cc:3030] Creating iterator
0812 06:36:46.781355 (+    21us) tablet_service.cc:3408] Waiting safe time to advance
0812 06:36:46.781364 (+     9us) tablet_service.cc:3415] Waiting for operations to commit
0812 06:36:48.436923 (+1655559us) tablet_service.cc:3431] All operations in snapshot committed. Waited for 1655550 microseconds
0812 06:36:48.437022 (+    99us) tablet_service.cc:3055] Iterator created
0812 06:36:48.450379 (+ 13357us) tablet_service.cc:3077] Iterator init: OK
0812 06:36:48.450407 (+    28us) tablet_service.cc:3120] has_more: true
0812 06:36:48.450444 (+    37us) tablet_service.cc:3137] Continuing scan request
0812 06:36:48.450489 (+    45us) tablet_service.cc:3201] Found scanner c4e018fa6f0349a68a775a6c4b818b1a for tablet 60ab298c91334b429b0400ade230cc6f, query id is 98b295c57d9c4ead9aee129af28d881f
0812 06:36:48.492541 (+ 42052us) inbound_call.cc:177] Queueing success response
Metrics: {"cfile_cache_hit":7,"cfile_cache_hit_bytes":11509,"rowset_iterators":2,"scanner_bytes_read":10845}
W20260812 06:36:48.494197 11912 scanner-internal.cc:458] Time spent opening tablet: real 1.714s	user 0.001s	sys 0.000s
I20260812 06:36:49.691123 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1007, attempt_no=0}) took 1248 ms. Trace:
I20260812 06:36:49.691322 11856 rpcz_store.cc:276] 0812 06:36:48.442392 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:48.442445 (+    53us) service_pool.cc:224] Handling call
0812 06:36:49.691107 (+1248662us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:48.442982 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:48.443073 (+    91us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:48.443077 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:48.443078 (+     1us) tablet.cc:662] Decoding operations
0812 06:36:48.446636 (+  3558us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:48.446645 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:48.446649 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:48.451282 (+  4633us) tablet.cc:701] Row locks acquired
0812 06:36:48.451284 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:48.451328 (+    44us) write_op.cc:270] Start()
0812 06:36:48.451353 (+    25us) write_op.cc:276] Timestamp: P: 1786516608451317 usec, L: 0
0812 06:36:48.451356 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:48.451530 (+   174us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:48.459083 (+  7553us) op_driver.cc:464] REPLICATION: finished
0812 06:36:48.459163 (+    80us) write_op.cc:301] APPLY: starting
0812 06:36:48.459183 (+    20us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:49.076781 (+617598us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:49.076797 (+    16us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:49.689085 (+612288us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:49.689516 (+   431us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=1000
0812 06:36:49.689523 (+     7us) write_op.cc:312] APPLY: finished
0812 06:36:49.690515 (+   992us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:49.690711 (+   196us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:49.690967 (+   256us) write_op.cc:454] Released schema lock
0812 06:36:49.691020 (+    53us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":30,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":37,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":181,"prepare.run_cpu_time_us":8608,"prepare.run_wall_time_us":9062,"replication_time_us":7705,"spinlock_wait_cycles":1213952,"thread_start_us":182,"threads_started":2}]]}
I20260812 06:36:50.133599 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 3.353s	user 0.065s	sys 0.004s
I20260812 06:36:50.988372 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1008, attempt_no=0}) took 1287 ms. Trace:
I20260812 06:36:50.988551 11856 rpcz_store.cc:276] 0812 06:36:49.701347 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:49.701394 (+    47us) service_pool.cc:224] Handling call
0812 06:36:50.988358 (+1286964us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:49.715033 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:49.715146 (+   113us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:49.715150 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:49.715152 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:49.720048 (+  4896us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:49.720059 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:49.720064 (+     5us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:49.739272 (+ 19208us) tablet.cc:701] Row locks acquired
0812 06:36:49.739274 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:49.739332 (+    58us) write_op.cc:270] Start()
0812 06:36:49.739362 (+    30us) write_op.cc:276] Timestamp: P: 1786516609739317 usec, L: 0
0812 06:36:49.739365 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:49.739582 (+   217us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:49.750223 (+ 10641us) op_driver.cc:464] REPLICATION: finished
0812 06:36:49.750317 (+    94us) write_op.cc:301] APPLY: starting
0812 06:36:49.750335 (+    18us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:50.376645 (+626310us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:50.376658 (+    13us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:50.986223 (+609565us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:50.986693 (+   470us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=1000
0812 06:36:50.986699 (+     6us) write_op.cc:312] APPLY: finished
0812 06:36:50.987795 (+  1096us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:50.987979 (+   184us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:50.988226 (+   247us) write_op.cc:454] Released schema lock
0812 06:36:50.988286 (+    60us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":36,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":38,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":13198,"prepare.run_cpu_time_us":12619,"prepare.run_wall_time_us":25158,"replication_time_us":10831,"spinlock_wait_cycles":2337280,"thread_start_us":182,"threads_started":2}]]}
I20260812 06:36:51.140827 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.007s	user 0.071s	sys 0.000s
W20260812 06:36:52.032374 11727 tablet_replica.cc:1406] Time spent applying in-flights took a long time: real 0.678s	user 0.004s	sys 0.000s
I20260812 06:36:52.032758 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1009, attempt_no=0}) took 1038 ms. Trace:
I20260812 06:36:52.032841 11856 rpcz_store.cc:276] 0812 06:36:50.994543 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:50.994583 (+    40us) service_pool.cc:224] Handling call
0812 06:36:52.032747 (+1038164us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:51.002518 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:51.002627 (+   109us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:51.002630 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:36:51.002632 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:51.006114 (+  3482us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:51.006123 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:51.006127 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:51.010536 (+  4409us) tablet.cc:701] Row locks acquired
0812 06:36:51.010538 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:51.010579 (+    41us) write_op.cc:270] Start()
0812 06:36:51.010605 (+    26us) write_op.cc:276] Timestamp: P: 1786516611010568 usec, L: 0
0812 06:36:51.010607 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:51.010770 (+   163us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:51.023028 (+ 12258us) op_driver.cc:464] REPLICATION: finished
0812 06:36:51.023094 (+    66us) write_op.cc:301] APPLY: starting
0812 06:36:51.023106 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:51.539223 (+516117us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:51.539235 (+    12us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:52.030575 (+491340us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:52.031065 (+   490us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=0
0812 06:36:52.031072 (+     7us) write_op.cc:312] APPLY: finished
0812 06:36:52.032182 (+  1110us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:52.032360 (+   178us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:52.032614 (+   254us) write_op.cc:454] Released schema lock
0812 06:36:52.032674 (+    60us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":34,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18746000,"num_ops":1000,"prepare.queue_time_us":7533,"prepare.run_cpu_time_us":8324,"prepare.run_wall_time_us":8325,"replication_time_us":12400,"spinlock_wait_cycles":1115008,"thread_start_us":157,"threads_started":2,"wal-append.queue_time_us":174}]]}
I20260812 06:36:52.033861 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: FlushMRSOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 3.592s	user 2.753s	sys 0.008s Metrics: {"bytes_written":396066,"cfile_init":1,"dirs.queue_time_us":1162,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":913,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":11958,"lbm_writes_lt_1ms":190,"peak_mem_usage":0,"rows_written":147999,"thread_start_us":79,"threads_started":1}
I20260812 06:36:52.034509 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f): 993538 bytes on disk
I20260812 06:36:52.034886 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: UndoDeltaBlockGCOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:36:52.035359 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling MajorDeltaCompactionOp(60ab298c91334b429b0400ade230cc6f): perf score=0.122010
I20260812 06:36:52.047102 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.906s	user 0.066s	sys 0.000s
I20260812 06:36:53.228250 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.181s	user 0.060s	sys 0.003s
I20260812 06:36:53.249429 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1010, attempt_no=0}) took 1211 ms. Trace:
I20260812 06:36:53.249504 11856 rpcz_store.cc:276] 0812 06:36:52.037573 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:52.037622 (+    49us) service_pool.cc:224] Handling call
0812 06:36:53.249419 (+1211797us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:52.038121 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:52.038212 (+    91us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:52.038216 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:52.038218 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:52.050177 (+ 11959us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:52.050187 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:52.050191 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:52.054740 (+  4549us) tablet.cc:701] Row locks acquired
0812 06:36:52.054742 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:52.054786 (+    44us) write_op.cc:270] Start()
0812 06:36:52.054811 (+    25us) write_op.cc:276] Timestamp: P: 1786516612054775 usec, L: 0
0812 06:36:52.054813 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:52.055015 (+   202us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:52.063057 (+  8042us) op_driver.cc:464] REPLICATION: finished
0812 06:36:52.063152 (+    95us) write_op.cc:301] APPLY: starting
0812 06:36:52.063165 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:52.659061 (+595896us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:52.659075 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:53.247850 (+588775us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:53.248152 (+   302us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=0
0812 06:36:53.248156 (+     4us) write_op.cc:312] APPLY: finished
0812 06:36:53.248895 (+   739us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:53.249078 (+   183us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:53.249306 (+   228us) write_op.cc:454] Released schema lock
0812 06:36:53.249352 (+    46us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":44,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":48,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":156,"prepare.run_cpu_time_us":9078,"prepare.run_wall_time_us":16966,"replication_time_us":8223,"spinlock_wait_cycles":683520,"thread_start_us":160,"threads_started":2,"wal-append.queue_time_us":185}]]}
I20260812 06:36:54.441810 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.213s	user 0.071s	sys 0.001s
I20260812 06:36:54.498831 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1011, attempt_no=0}) took 1243 ms. Trace:
I20260812 06:36:54.499032 11856 rpcz_store.cc:276] 0812 06:36:53.255479 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:53.255519 (+    40us) service_pool.cc:224] Handling call
0812 06:36:54.498813 (+1243294us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:53.267017 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:53.267107 (+    90us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:53.267110 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:36:53.267112 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:53.270664 (+  3552us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:53.270673 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:53.270678 (+     5us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:53.275261 (+  4583us) tablet.cc:701] Row locks acquired
0812 06:36:53.275263 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:53.275306 (+    43us) write_op.cc:270] Start()
0812 06:36:53.275330 (+    24us) write_op.cc:276] Timestamp: P: 1786516613275296 usec, L: 0
0812 06:36:53.275332 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:53.275502 (+   170us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:53.284902 (+  9400us) op_driver.cc:464] REPLICATION: finished
0812 06:36:53.284967 (+    65us) write_op.cc:301] APPLY: starting
0812 06:36:53.284979 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:53.879624 (+594645us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:53.879639 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:54.496652 (+617013us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:54.497110 (+   458us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=0
0812 06:36:54.497117 (+     7us) write_op.cc:312] APPLY: finished
0812 06:36:54.498237 (+  1120us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:54.498413 (+   176us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:54.498661 (+   248us) write_op.cc:454] Released schema lock
0812 06:36:54.498722 (+    61us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":31,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18746000,"num_ops":1000,"prepare.queue_time_us":11161,"prepare.run_cpu_time_us":8563,"prepare.run_wall_time_us":17863,"replication_time_us":9546,"spinlock_wait_cycles":609792,"thread_start_us":167,"threads_started":2}]]}
I20260812 06:36:55.290963 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.849s	user 0.063s	sys 0.000s
W20260812 06:36:55.471592 11727 tablet_replica.cc:1406] Time spent applying in-flights took a long time: real 0.708s	user 0.001s	sys 0.000s
I20260812 06:36:55.473760 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: MajorDeltaCompactionOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 3.438s	user 2.691s	sys 0.007s Metrics: {"cfile_cache_hit":52,"cfile_cache_hit_bytes":80843,"cfile_init":2,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":133,"lbm_reads_lt_1ms":8,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":58,"peak_mem_usage":206486,"reinsert_count":0,"thread_start_us":153,"threads_started":3,"update_count":9094}
I20260812 06:36:55.474220 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling LogGCOp(60ab298c91334b429b0400ade230cc6f): free 8349025 bytes of WAL
I20260812 06:36:55.474444 11727 log_reader.cc:385] T 60ab298c91334b429b0400ade230cc6f: removed 1 log segments from log reader
I20260812 06:36:55.474507 11727 log.cc:1079] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: Deleting log segment in path: /tmp/dist-test-task8CbS3g/test-tmp/update_scan_delta_compact-test.0.UpdateScanDeltaCompactionTest.TestAll.1786516563640408-11584-0/minicluster-data/ts-0-root/wals/60ab298c91334b429b0400ade230cc6f/wal-000000001 (ops 1-863)
I20260812 06:36:55.476590 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: LogGCOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:36:55.476907 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f): perf score=0.012453
I20260812 06:36:56.677451 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1013, attempt_no=0}) took 1199 ms. Trace:
I20260812 06:36:56.677635 11856 rpcz_store.cc:276] 0812 06:36:55.477769 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:55.477823 (+    54us) service_pool.cc:224] Handling call
0812 06:36:56.677438 (+1199615us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:55.495035 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:55.495132 (+    97us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:55.495137 (+     5us) write_op.cc:435] Acquired schema lock
0812 06:36:55.495138 (+     1us) tablet.cc:662] Decoding operations
0812 06:36:55.498712 (+  3574us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:55.498722 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:55.498726 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:55.503383 (+  4657us) tablet.cc:701] Row locks acquired
0812 06:36:55.503385 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:55.503434 (+    49us) write_op.cc:270] Start()
0812 06:36:55.503461 (+    27us) write_op.cc:276] Timestamp: P: 1786516615503422 usec, L: 0
0812 06:36:55.503464 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:55.503657 (+   193us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:55.505859 (+  2202us) op_driver.cc:464] REPLICATION: finished
0812 06:36:55.505922 (+    63us) write_op.cc:301] APPLY: starting
0812 06:36:55.505933 (+    11us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:56.079363 (+573430us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:56.079379 (+    16us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:56.675394 (+596015us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:56.675862 (+   468us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:56.675868 (+     6us) write_op.cc:312] APPLY: finished
0812 06:36:56.676911 (+  1043us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:56.677077 (+   166us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:56.677310 (+   233us) write_op.cc:454] Released schema lock
0812 06:36:56.677367 (+    57us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":34,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":32,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":16851,"prepare.run_cpu_time_us":8666,"prepare.run_wall_time_us":8704,"replication_time_us":2373,"spinlock_wait_cycles":682752,"thread_start_us":212,"threads_started":2}]]}
I20260812 06:36:56.748754 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.457s	user 0.065s	sys 0.004s
I20260812 06:36:57.699278 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.950s	user 0.072s	sys 0.000s
I20260812 06:36:57.880399 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1014, attempt_no=0}) took 1196 ms. Trace:
I20260812 06:36:57.880586 11856 rpcz_store.cc:276] 0812 06:36:56.683599 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:56.690616 (+  7017us) service_pool.cc:224] Handling call
0812 06:36:57.880382 (+1189766us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:56.698188 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:56.698291 (+   103us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:56.698295 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:56.698296 (+     1us) tablet.cc:662] Decoding operations
0812 06:36:56.701785 (+  3489us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:56.701794 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:56.701798 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:56.706336 (+  4538us) tablet.cc:701] Row locks acquired
0812 06:36:56.706339 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:36:56.706384 (+    45us) write_op.cc:270] Start()
0812 06:36:56.706410 (+    26us) write_op.cc:276] Timestamp: P: 1786516616706372 usec, L: 0
0812 06:36:56.706412 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:56.706586 (+   174us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:56.709966 (+  3380us) op_driver.cc:464] REPLICATION: finished
0812 06:36:56.710049 (+    83us) write_op.cc:301] APPLY: starting
0812 06:36:56.710061 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:57.285046 (+574985us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:57.285060 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:57.878311 (+593251us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:57.878733 (+   422us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:57.878740 (+     7us) write_op.cc:312] APPLY: finished
0812 06:36:57.879783 (+  1043us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:57.880017 (+   234us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:57.880237 (+   220us) write_op.cc:454] Released schema lock
0812 06:36:57.880286 (+    49us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":30,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18746000,"num_ops":1000,"prepare.queue_time_us":7185,"prepare.run_cpu_time_us":8465,"prepare.run_wall_time_us":11657,"replication_time_us":3537,"spinlock_wait_cycles":675968,"thread_start_us":163,"threads_started":2}]]}
I20260812 06:36:59.130131 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1015, attempt_no=0}) took 1243 ms. Trace:
I20260812 06:36:59.130307 11856 rpcz_store.cc:276] 0812 06:36:57.886550 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:57.886602 (+    52us) service_pool.cc:224] Handling call
0812 06:36:59.130118 (+1243516us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:57.891082 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:57.891191 (+   109us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:57.891195 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:57.891197 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:57.896072 (+  4875us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:57.896082 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:57.896086 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:57.903877 (+  7791us) tablet.cc:701] Row locks acquired
0812 06:36:57.903879 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:57.903929 (+    50us) write_op.cc:270] Start()
0812 06:36:57.903958 (+    29us) write_op.cc:276] Timestamp: P: 1786516617903918 usec, L: 0
0812 06:36:57.903961 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:36:57.904213 (+   252us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:57.911071 (+  6858us) op_driver.cc:464] REPLICATION: finished
0812 06:36:57.911142 (+    71us) write_op.cc:301] APPLY: starting
0812 06:36:57.911157 (+    15us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:58.507633 (+596476us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:58.507647 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:36:59.128056 (+620409us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:36:59.128523 (+   467us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:36:59.128537 (+    14us) write_op.cc:312] APPLY: finished
0812 06:36:59.129593 (+  1056us) log.cc:844] Serialized 8020 byte log entry
0812 06:36:59.129754 (+   161us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:36:59.129985 (+   231us) write_op.cc:454] Released schema lock
0812 06:36:59.130043 (+    58us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":36,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":39,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":4071,"prepare.run_cpu_time_us":12537,"prepare.run_wall_time_us":15919,"replication_time_us":7087,"spinlock_wait_cycles":1132416,"thread_start_us":171,"threads_started":2}]]}
I20260812 06:36:59.160804 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.461s	user 0.071s	sys 0.000s
I20260812 06:37:00.359395 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1016, attempt_no=0}) took 1219 ms. Trace:
I20260812 06:37:00.359532 11856 rpcz_store.cc:276] 0812 06:36:59.139642 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:59.139680 (+    38us) service_pool.cc:224] Handling call
0812 06:37:00.359378 (+1219698us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:36:59.143688 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:36:59.146570 (+  2882us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:36:59.146574 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:36:59.146576 (+     2us) tablet.cc:662] Decoding operations
0812 06:36:59.150023 (+  3447us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:36:59.150032 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:36:59.150036 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:36:59.154329 (+  4293us) tablet.cc:701] Row locks acquired
0812 06:36:59.154331 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:36:59.154376 (+    45us) write_op.cc:270] Start()
0812 06:36:59.154401 (+    25us) write_op.cc:276] Timestamp: P: 1786516619154365 usec, L: 0
0812 06:36:59.154403 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:36:59.154581 (+   178us) log.cc:844] Serialized 52317 byte log entry
0812 06:36:59.162573 (+  7992us) op_driver.cc:464] REPLICATION: finished
0812 06:36:59.162689 (+   116us) write_op.cc:301] APPLY: starting
0812 06:36:59.162702 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:36:59.740758 (+578056us) tablet.cc:1370] finished BulkCheckPresence
0812 06:36:59.740775 (+    17us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:00.356207 (+615432us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:00.356677 (+   470us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:00.356683 (+     6us) write_op.cc:312] APPLY: finished
0812 06:37:00.357666 (+   983us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:00.358972 (+  1306us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:00.359226 (+   254us) write_op.cc:454] Released schema lock
0812 06:37:00.359283 (+    57us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":57,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18746000,"num_ops":1000,"prepare.queue_time_us":3664,"prepare.run_cpu_time_us":8213,"prepare.run_wall_time_us":12148,"replication_time_us":8086,"spinlock_wait_cycles":1595776,"thread_start_us":181,"threads_started":2,"wal-append.queue_time_us":212}]]}
I20260812 06:37:00.456169 11752 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Scan from 127.0.0.1:34730 (request call id 1605) took 1294 ms. Trace:
I20260812 06:37:00.456359 11752 rpcz_store.cc:276] 0812 06:36:59.161687 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:36:59.161720 (+    33us) service_pool.cc:224] Handling call
0812 06:36:59.161830 (+   110us) tablet_service.cc:2890] Created scanner 93468af9a3224467893c0f51ef58d083 for tablet 60ab298c91334b429b0400ade230cc6f, query id is aa18df6b547242c9a0fb8c4cf3ce6483
0812 06:36:59.162010 (+   180us) tablet_service.cc:3030] Creating iterator
0812 06:36:59.162038 (+    28us) tablet_service.cc:3408] Waiting safe time to advance
0812 06:36:59.162047 (+     9us) tablet_service.cc:3415] Waiting for operations to commit
0812 06:37:00.357924 (+1195877us) tablet_service.cc:3431] All operations in snapshot committed. Waited for 1195871 microseconds
0812 06:37:00.358032 (+   108us) tablet_service.cc:3055] Iterator created
0812 06:37:00.360356 (+  2324us) tablet_service.cc:3077] Iterator init: OK
0812 06:37:00.360389 (+    33us) tablet_service.cc:3120] has_more: true
0812 06:37:00.360429 (+    40us) tablet_service.cc:3137] Continuing scan request
0812 06:37:00.360481 (+    52us) tablet_service.cc:3201] Found scanner 93468af9a3224467893c0f51ef58d083 for tablet 60ab298c91334b429b0400ade230cc6f, query id is aa18df6b547242c9a0fb8c4cf3ce6483
0812 06:37:00.456151 (+ 95670us) inbound_call.cc:177] Queueing success response
Metrics: {"cfile_cache_hit":7,"cfile_cache_hit_bytes":11872,"rowset_iterators":3,"scanner_bytes_read":10866}
W20260812 06:37:00.457860 11912 scanner-internal.cc:458] Time spent opening tablet: real 1.297s	user 0.000s	sys 0.000s
I20260812 06:37:01.542747 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 2.382s	user 0.068s	sys 0.004s
I20260812 06:37:01.613201 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1017, attempt_no=0}) took 1245 ms. Trace:
I20260812 06:37:01.613374 11856 rpcz_store.cc:276] 0812 06:37:00.368216 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:00.368275 (+    59us) service_pool.cc:224] Handling call
0812 06:37:01.613187 (+1244912us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:00.379051 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:00.379166 (+   115us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:00.379170 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:00.379173 (+     3us) tablet.cc:662] Decoding operations
0812 06:37:00.384087 (+  4914us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:00.384099 (+    12us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:00.384103 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:00.399206 (+ 15103us) tablet.cc:701] Row locks acquired
0812 06:37:00.399209 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:00.399269 (+    60us) write_op.cc:270] Start()
0812 06:37:00.399303 (+    34us) write_op.cc:276] Timestamp: P: 1786516620399255 usec, L: 0
0812 06:37:00.399305 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:00.399526 (+   221us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:00.411029 (+ 11503us) op_driver.cc:464] REPLICATION: finished
0812 06:37:00.411108 (+    79us) write_op.cc:301] APPLY: starting
0812 06:37:00.411124 (+    16us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:00.998306 (+587182us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:00.998320 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:01.611119 (+612799us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:01.611579 (+   460us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:01.611585 (+     6us) write_op.cc:312] APPLY: finished
0812 06:37:01.612653 (+  1068us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:01.612818 (+   165us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:01.613055 (+   237us) write_op.cc:454] Released schema lock
0812 06:37:01.613111 (+    56us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":39,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":37,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":10354,"prepare.run_cpu_time_us":12575,"prepare.run_wall_time_us":31291,"replication_time_us":11689,"spinlock_wait_cycles":1682688,"thread_start_us":182,"threads_started":2}]]}
I20260812 06:37:02.402757 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.859s	user 0.071s	sys 0.000s
I20260812 06:37:02.868537 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1018, attempt_no=0}) took 1245 ms. Trace:
I20260812 06:37:02.868723 11856 rpcz_store.cc:276] 0812 06:37:01.622933 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:01.623045 (+   112us) service_pool.cc:224] Handling call
0812 06:37:02.868521 (+1245476us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:01.623594 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:01.623701 (+   107us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:01.623705 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:01.623707 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:01.628559 (+  4852us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:01.628688 (+   129us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:01.628719 (+    31us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:01.635768 (+  7049us) tablet.cc:701] Row locks acquired
0812 06:37:01.635770 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:01.635819 (+    49us) write_op.cc:270] Start()
0812 06:37:01.635848 (+    29us) write_op.cc:276] Timestamp: P: 1786516621635806 usec, L: 0
0812 06:37:01.635850 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:01.636048 (+   198us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:01.642461 (+  6413us) op_driver.cc:464] REPLICATION: finished
0812 06:37:01.642557 (+    96us) write_op.cc:301] APPLY: starting
0812 06:37:01.642569 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:02.254097 (+611528us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:02.254111 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:02.866370 (+612259us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:02.866829 (+   459us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:02.866835 (+     6us) write_op.cc:312] APPLY: finished
0812 06:37:02.867939 (+  1104us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:02.868128 (+   189us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:02.868368 (+   240us) write_op.cc:454] Released schema lock
0812 06:37:02.868426 (+    58us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":30,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18746000,"num_ops":1000,"prepare.queue_time_us":201,"prepare.run_cpu_time_us":12406,"prepare.run_wall_time_us":12518,"replication_time_us":6588,"spinlock_wait_cycles":467328,"thread_start_us":169,"threads_started":2}]]}
I20260812 06:37:03.309703 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.907s	user 0.066s	sys 0.004s
I20260812 06:37:04.123098 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1019, attempt_no=0}) took 1248 ms. Trace:
I20260812 06:37:04.123271 11856 rpcz_store.cc:276] 0812 06:37:02.874708 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:02.874754 (+    46us) service_pool.cc:224] Handling call
0812 06:37:04.123082 (+1248328us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:02.883052 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:02.883175 (+   123us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:02.883180 (+     5us) write_op.cc:435] Acquired schema lock
0812 06:37:02.883182 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:02.888299 (+  5117us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:02.888311 (+    12us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:02.888316 (+     5us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:02.907508 (+ 19192us) tablet.cc:701] Row locks acquired
0812 06:37:02.907511 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:02.907569 (+    58us) write_op.cc:270] Start()
0812 06:37:02.907600 (+    31us) write_op.cc:276] Timestamp: P: 1786516622907556 usec, L: 0
0812 06:37:02.907603 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:37:02.907809 (+   206us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:02.909358 (+  1549us) op_driver.cc:464] REPLICATION: finished
0812 06:37:02.909492 (+   134us) write_op.cc:301] APPLY: starting
0812 06:37:02.909507 (+    15us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:03.508630 (+599123us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:03.508645 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:04.120963 (+612318us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:04.121406 (+   443us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:04.121413 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:04.122508 (+  1095us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:04.122678 (+   170us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:04.122945 (+   267us) write_op.cc:454] Released schema lock
0812 06:37:04.123001 (+    56us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":76,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":33,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":7881,"prepare.run_cpu_time_us":12785,"prepare.run_wall_time_us":24830,"replication_time_us":1724,"spinlock_wait_cycles":516736,"thread_start_us":157,"threads_started":2}]]}
I20260812 06:37:04.268141 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.957s	user 0.070s	sys 0.000s
I20260812 06:37:05.162422 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.894s	user 0.070s	sys 0.000s
I20260812 06:37:05.396080 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1020, attempt_no=0}) took 1264 ms. Trace:
I20260812 06:37:05.396271 11856 rpcz_store.cc:276] 0812 06:37:04.132000 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:04.132050 (+    50us) service_pool.cc:224] Handling call
0812 06:37:05.396062 (+1264012us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:04.143078 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:04.143192 (+   114us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:04.143197 (+     5us) write_op.cc:435] Acquired schema lock
0812 06:37:04.143199 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:04.160361 (+ 17162us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:04.160372 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:04.160376 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:04.167625 (+  7249us) tablet.cc:701] Row locks acquired
0812 06:37:04.167628 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:04.167688 (+    60us) write_op.cc:270] Start()
0812 06:37:04.167718 (+    30us) write_op.cc:276] Timestamp: P: 1786516624167673 usec, L: 0
0812 06:37:04.167720 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:04.167965 (+   245us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:04.168733 (+   768us) op_driver.cc:464] REPLICATION: finished
0812 06:37:04.168807 (+    74us) write_op.cc:301] APPLY: starting
0812 06:37:04.168821 (+    14us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:04.769844 (+601023us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:04.769860 (+    16us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:05.393854 (+623994us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:05.394337 (+   483us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:05.394344 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:05.395427 (+  1083us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:05.395634 (+   207us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:05.395899 (+   265us) write_op.cc:454] Released schema lock
0812 06:37:05.395958 (+    59us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":36,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":35,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":10607,"prepare.run_cpu_time_us":13093,"prepare.run_wall_time_us":25533,"replication_time_us":968,"spinlock_wait_cycles":871040,"thread_start_us":163,"threads_started":2}]]}
I20260812 06:37:06.080755 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.918s	user 0.066s	sys 0.004s
I20260812 06:37:06.634395 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1021, attempt_no=0}) took 1228 ms. Trace:
I20260812 06:37:06.634595 11856 rpcz_store.cc:276] 0812 06:37:05.406055 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:05.410973 (+  4918us) service_pool.cc:224] Handling call
0812 06:37:06.634377 (+1223404us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:05.419045 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:05.419163 (+   118us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:05.419168 (+     5us) write_op.cc:435] Acquired schema lock
0812 06:37:05.419170 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:05.434982 (+ 15812us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:05.434993 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:05.434997 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:05.439538 (+  4541us) tablet.cc:701] Row locks acquired
0812 06:37:05.439541 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:05.439595 (+    54us) write_op.cc:270] Start()
0812 06:37:05.439624 (+    29us) write_op.cc:276] Timestamp: P: 1786516625439583 usec, L: 0
0812 06:37:05.439626 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:05.439841 (+   215us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:05.440526 (+   685us) op_driver.cc:464] REPLICATION: finished
0812 06:37:05.440590 (+    64us) write_op.cc:301] APPLY: starting
0812 06:37:05.440602 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:06.037331 (+596729us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:06.037346 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:06.632346 (+595000us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:06.632764 (+   418us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:06.632771 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:06.633755 (+   984us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:06.633967 (+   212us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:06.634222 (+   255us) write_op.cc:454] Released schema lock
0812 06:37:06.634279 (+    57us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":30,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18746000,"num_ops":1000,"prepare.queue_time_us":7664,"prepare.run_cpu_time_us":9591,"prepare.run_wall_time_us":21344,"replication_time_us":870,"spinlock_wait_cycles":339328,"thread_start_us":189,"threads_started":2}]]}
W20260812 06:37:06.731909 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.651s	user 0.001s	sys 0.000s
I20260812 06:37:07.838987 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1022, attempt_no=0}) took 1195 ms. Trace:
I20260812 06:37:07.839164 11856 rpcz_store.cc:276] 0812 06:37:06.643799 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:06.643845 (+    46us) service_pool.cc:224] Handling call
0812 06:37:07.838971 (+1195126us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:06.655029 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:06.655130 (+   101us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:06.655133 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:37:06.655135 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:06.658639 (+  3504us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:06.658648 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:06.658652 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:06.663130 (+  4478us) tablet.cc:701] Row locks acquired
0812 06:37:06.663133 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:06.663178 (+    45us) write_op.cc:270] Start()
0812 06:37:06.663205 (+    27us) write_op.cc:276] Timestamp: P: 1786516626663168 usec, L: 0
0812 06:37:06.663207 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:06.663381 (+   174us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:06.675030 (+ 11649us) op_driver.cc:464] REPLICATION: finished
0812 06:37:06.675115 (+    85us) write_op.cc:301] APPLY: starting
0812 06:37:06.675132 (+    17us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:07.233760 (+558628us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:07.233774 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:07.836857 (+603083us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:07.837328 (+   471us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:07.837334 (+     6us) write_op.cc:312] APPLY: finished
0812 06:37:07.838390 (+  1056us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:07.838559 (+   169us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:07.838819 (+   260us) write_op.cc:454] Released schema lock
0812 06:37:07.838867 (+    48us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":29,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18754212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":40,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":10818,"prepare.run_cpu_time_us":8448,"prepare.run_wall_time_us":19980,"replication_time_us":11797,"spinlock_wait_cycles":474240,"thread_start_us":155,"threads_started":2}]]}
I20260812 06:37:07.900843 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.820s	user 0.071s	sys 0.000s
I20260812 06:37:08.724858 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.824s	user 0.061s	sys 0.000s
I20260812 06:37:10.609323 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.884s	user 0.060s	sys 0.004s
I20260812 06:37:10.725658 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1024, attempt_no=0}) took 1887 ms. Trace:
I20260812 06:37:10.725852 11856 rpcz_store.cc:276] 0812 06:37:08.838702 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:08.850965 (+ 12263us) service_pool.cc:224] Handling call
0812 06:37:10.725638 (+1874673us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:08.865922 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:08.866024 (+   102us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:08.866028 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:08.866030 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:08.869720 (+  3690us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:08.869732 (+    12us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:08.869736 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:08.874318 (+  4582us) tablet.cc:701] Row locks acquired
0812 06:37:08.874320 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:08.874376 (+    56us) write_op.cc:270] Start()
0812 06:37:08.874405 (+    29us) write_op.cc:276] Timestamp: P: 1786516628874362 usec, L: 0
0812 06:37:08.874408 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:37:08.874614 (+   206us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:08.875337 (+   723us) op_driver.cc:464] REPLICATION: finished
0812 06:37:08.875421 (+    84us) write_op.cc:301] APPLY: starting
0812 06:37:08.875437 (+    16us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:09.444919 (+569482us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:09.444934 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:10.723027 (+1278093us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:10.723501 (+   474us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=3000,key_file_lookups=3000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:10.723508 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:10.724951 (+  1443us) log.cc:844] Serialized 14020 byte log entry
0812 06:37:10.725166 (+   215us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:10.725436 (+   270us) write_op.cc:454] Released schema lock
0812 06:37:10.725497 (+    61us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":32,"cfile_cache_hit":6000,"cfile_cache_hit_bytes":28184772,"cfile_cache_miss":6,"cfile_cache_miss_bytes":32359,"cfile_init":1,"lbm_read_time_us":213,"lbm_reads_lt_1ms":10,"num_ops":1000,"prepare.queue_time_us":14568,"prepare.run_cpu_time_us":8752,"prepare.run_wall_time_us":8758,"replication_time_us":907,"spinlock_wait_cycles":711808,"thread_start_us":216,"threads_started":2}]]}
I20260812 06:37:12.232998 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.623s	user 0.069s	sys 0.001s
W20260812 06:37:12.317572 11727 tablet_replica.cc:1406] Time spent applying in-flights took a long time: real 1.061s	user 0.000s	sys 0.000s
I20260812 06:37:12.317962 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1025, attempt_no=0}) took 1585 ms. Trace:
I20260812 06:37:12.318035 11856 rpcz_store.cc:276] 0812 06:37:10.732572 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:10.732618 (+    46us) service_pool.cc:224] Handling call
0812 06:37:12.317950 (+1585332us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:10.743063 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:10.743157 (+    94us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:10.743161 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:10.743163 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:10.746760 (+  3597us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:10.746769 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:10.746773 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:10.759391 (+ 12618us) tablet.cc:701] Row locks acquired
0812 06:37:10.759394 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:10.759440 (+    46us) write_op.cc:270] Start()
0812 06:37:10.759466 (+    26us) write_op.cc:276] Timestamp: P: 1786516630759428 usec, L: 0
0812 06:37:10.759468 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:10.759640 (+   172us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:10.769792 (+ 10152us) op_driver.cc:464] REPLICATION: finished
0812 06:37:10.769877 (+    85us) write_op.cc:301] APPLY: starting
0812 06:37:10.769890 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:11.365186 (+595296us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:11.365199 (+    13us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:12.316035 (+950836us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:12.316390 (+   355us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=3000,key_file_lookups=3000,delta_file_lookups=1000,mrs_lookups=0
0812 06:37:12.316395 (+     5us) write_op.cc:312] APPLY: finished
0812 06:37:12.317369 (+   974us) log.cc:844] Serialized 14020 byte log entry
0812 06:37:12.317551 (+   182us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:12.317817 (+   266us) write_op.cc:454] Released schema lock
0812 06:37:12.317871 (+    54us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":33,"cfile_cache_hit":6002,"cfile_cache_hit_bytes":28194212,"cfile_cache_miss":2,"cfile_cache_miss_bytes":8212,"cfile_init":1,"lbm_read_time_us":146,"lbm_reads_lt_1ms":6,"num_ops":1000,"prepare.queue_time_us":10084,"prepare.run_cpu_time_us":8642,"prepare.run_wall_time_us":23929,"replication_time_us":10304,"spinlock_wait_cycles":955904,"thread_start_us":142,"threads_started":2,"wal-append.queue_time_us":191}]]}
I20260812 06:37:12.320102 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: CompactRowSetsOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 16.843s	user 14.749s	sys 0.066s Metrics: {"bytes_written":92263,"cfile_cache_hit":181,"cfile_cache_hit_bytes":661215,"cfile_cache_miss":1003,"cfile_cache_miss_bytes":13496571,"cfile_init":1,"delete_count":0,"delta_iterators_relevant":6,"dirs.queue_time_us":1219,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":887,"drs_written":1,"lbm_read_time_us":30847,"lbm_reads_lt_1ms":1007,"lbm_write_time_us":71263,"lbm_writes_lt_1ms":1210,"num_input_rowsets":2,"peak_mem_usage":14016100,"reinsert_count":0,"rows_written":1000000,"spinlock_wait_cycles":3072,"thread_start_us":89,"threads_started":1,"update_count":24000}
I20260812 06:37:12.321211 11830 maintenance_manager.cc:419] P 0ad813103238463fb17e46a8f942f3b6: Scheduling MajorDeltaCompactionOp(60ab298c91334b429b0400ade230cc6f): perf score=0.271573
I20260812 06:37:13.222635 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.989s	user 0.070s	sys 0.000s
I20260812 06:37:13.552672 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1026, attempt_no=0}) took 1226 ms. Trace:
I20260812 06:37:13.552863 11856 rpcz_store.cc:276] 0812 06:37:12.326244 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:12.326286 (+    42us) service_pool.cc:224] Handling call
0812 06:37:13.552660 (+1226374us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:12.334422 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:12.334520 (+    98us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:12.334524 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:12.334525 (+     1us) tablet.cc:662] Decoding operations
0812 06:37:12.339367 (+  4842us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:12.339378 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:12.339382 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:12.358637 (+ 19255us) tablet.cc:701] Row locks acquired
0812 06:37:12.358640 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:12.358689 (+    49us) write_op.cc:270] Start()
0812 06:37:12.358716 (+    27us) write_op.cc:276] Timestamp: P: 1786516632358676 usec, L: 0
0812 06:37:12.358719 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:37:12.358909 (+   190us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:12.360382 (+  1473us) op_driver.cc:464] REPLICATION: finished
0812 06:37:12.360455 (+    73us) write_op.cc:301] APPLY: starting
0812 06:37:12.360468 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:12.930425 (+569957us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:12.930439 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:13.550482 (+620043us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:13.550983 (+   501us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=0
0812 06:37:13.550989 (+     6us) write_op.cc:312] APPLY: finished
0812 06:37:13.552083 (+  1094us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:13.552252 (+   169us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:13.552524 (+   272us) write_op.cc:454] Released schema lock
0812 06:37:13.552584 (+    60us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":38,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":18880000,"num_ops":1000,"prepare.queue_time_us":7805,"prepare.run_cpu_time_us":12544,"prepare.run_wall_time_us":24577,"replication_time_us":1638,"spinlock_wait_cycles":875648,"thread_start_us":151,"threads_started":2}]]}
I20260812 06:37:14.266698 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.043s	user 0.065s	sys 0.004s
I20260812 06:37:15.083127 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1027, attempt_no=0}) took 1518 ms. Trace:
I20260812 06:37:15.083276 11856 rpcz_store.cc:276] 0812 06:37:13.564310 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:13.564357 (+    47us) service_pool.cc:224] Handling call
0812 06:37:15.083112 (+1518755us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:13.572569 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:13.572679 (+   110us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:13.572683 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:13.572685 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:13.578008 (+  5323us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:13.578017 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:13.578021 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:13.582402 (+  4381us) tablet.cc:701] Row locks acquired
0812 06:37:13.582404 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:13.582448 (+    44us) write_op.cc:270] Start()
0812 06:37:13.582473 (+    25us) write_op.cc:276] Timestamp: P: 1786516633582437 usec, L: 0
0812 06:37:13.582475 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:13.582644 (+   169us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:13.589857 (+  7213us) op_driver.cc:464] REPLICATION: finished
0812 06:37:13.589983 (+   126us) write_op.cc:301] APPLY: starting
0812 06:37:13.589996 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:14.374812 (+784816us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:14.374825 (+    13us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:15.080949 (+706124us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:15.081408 (+   459us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=2000,mrs_lookups=0
0812 06:37:15.081415 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:15.082483 (+  1068us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:15.082676 (+   193us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:15.082978 (+   302us) write_op.cc:454] Released schema lock
0812 06:37:15.083037 (+    59us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":31,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18888212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":44,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":7859,"prepare.run_cpu_time_us":8382,"prepare.run_wall_time_us":17149,"replication_time_us":7353,"spinlock_wait_cycles":2200960,"thread_start_us":206,"threads_started":2}]]}
I20260812 06:37:15.325740 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.059s	user 0.066s	sys 0.000s
W20260812 06:37:16.140260 11727 tablet_replica.cc:1406] Time spent applying in-flights took a long time: real 0.395s	user 0.001s	sys 0.000s
I20260812 06:37:16.140688 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1028, attempt_no=0}) took 1051 ms. Trace:
I20260812 06:37:16.140772 11856 rpcz_store.cc:276] 0812 06:37:15.089386 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:15.089432 (+    46us) service_pool.cc:224] Handling call
0812 06:37:16.140672 (+1051240us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:15.097665 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:15.097773 (+   108us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:15.097776 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:37:15.097778 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:15.107608 (+  9830us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:15.107619 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:15.107624 (+     5us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:15.114719 (+  7095us) tablet.cc:701] Row locks acquired
0812 06:37:15.114722 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:15.118785 (+  4063us) spinlock_profiling.cc:243] Waited 1.02 ms on lock 0x55d40ac14fc8. stack: 00007f75f278ed35 00007f75f278f325 00007f75f1c7782d 00007f75f49ae4a0 00007f75f49ae4d7 00007f75f49ae9f2 00007f75f3716f6b 00007f75f37164cc 00007f75f3715d9a 00007f75f371b72a 000055d3ec94c009 00007f75f27b2326 00007f75f27b2c4e 00007f75f27b439a 000055d3ec94c009 00007f75f27a2711
0812 06:37:15.119600 (+   815us) write_op.cc:270] Start()
0812 06:37:15.119641 (+    41us) write_op.cc:276] Timestamp: P: 1786516635119583 usec, L: 0
0812 06:37:15.119645 (+     4us) op_driver.cc:348] REPLICATION: starting
0812 06:37:15.122698 (+  3053us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:15.123372 (+   674us) op_driver.cc:464] REPLICATION: finished
0812 06:37:15.123465 (+    93us) write_op.cc:301] APPLY: starting
0812 06:37:15.123476 (+    11us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:15.703358 (+579882us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:15.703360 (+     2us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:16.138357 (+434997us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:16.138843 (+   486us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=1069,mrs_lookups=0
0812 06:37:16.138850 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:16.140002 (+  1152us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:16.140244 (+   242us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:16.140521 (+   277us) write_op.cc:454] Released schema lock
0812 06:37:16.140572 (+    51us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":29,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18894707,"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"num_ops":1000,"prepare.queue_time_us":7884,"prepare.run_cpu_time_us":11467,"prepare.run_wall_time_us":25102,"replication_time_us":3702,"spinlock_wait_cycles":2900352,"thread_start_us":210,"threads_started":2,"wal-append.queue_time_us":197}]]}
I20260812 06:37:16.142565 11727 maintenance_manager.cc:643] P 0ad813103238463fb17e46a8f942f3b6: MajorDeltaCompactionOp(60ab298c91334b429b0400ade230cc6f) complete. Timing: real 3.821s	user 3.317s	sys 0.006s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":33615,"cfile_cache_miss":38,"cfile_cache_miss_bytes":112120,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":1363,"lbm_reads_lt_1ms":54,"lbm_write_time_us":3759,"lbm_writes_lt_1ms":74,"peak_mem_usage":546362,"reinsert_count":0,"thread_start_us":166,"threads_started":3,"update_count":24000}
W20260812 06:37:16.160519 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.834s	user 0.001s	sys 0.000s
I20260812 06:37:17.194554 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.868s	user 0.062s	sys 0.000s
W20260812 06:37:17.931360 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.736s	user 0.000s	sys 0.000s
I20260812 06:37:18.920202 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.725s	user 0.064s	sys 0.000s
I20260812 06:37:18.948629 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1031, attempt_no=0}) took 1032 ms. Trace:
I20260812 06:37:18.948731 11856 rpcz_store.cc:276] 0812 06:37:17.916572 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:17.916622 (+    50us) service_pool.cc:224] Handling call
0812 06:37:18.948613 (+1031991us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:17.917254 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:17.917351 (+    97us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:17.917355 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:17.917357 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:17.920843 (+  3486us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:17.920853 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:17.920856 (+     3us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:17.925143 (+  4287us) tablet.cc:701] Row locks acquired
0812 06:37:17.925145 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:17.925197 (+    52us) write_op.cc:270] Start()
0812 06:37:17.925223 (+    26us) write_op.cc:276] Timestamp: P: 1786516637925186 usec, L: 0
0812 06:37:17.925226 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:37:17.925401 (+   175us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:17.926069 (+   668us) op_driver.cc:464] REPLICATION: finished
0812 06:37:17.926130 (+    61us) write_op.cc:301] APPLY: starting
0812 06:37:17.926141 (+    11us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:18.415853 (+489712us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:18.415868 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:18.947027 (+531159us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:18.947327 (+   300us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:18.947332 (+     5us) write_op.cc:312] APPLY: finished
0812 06:37:18.948035 (+   703us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:18.948221 (+   186us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:18.948480 (+   259us) write_op.cc:454] Released schema lock
0812 06:37:18.948529 (+    49us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":29,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":18888212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":34,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":229,"prepare.run_cpu_time_us":8195,"prepare.run_wall_time_us":8699,"replication_time_us":825,"spinlock_wait_cycles":658560,"thread_start_us":198,"threads_started":2,"wal-append.queue_time_us":198}]]}
I20260812 06:37:19.993503 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.073s	user 0.065s	sys 0.000s
W20260812 06:37:20.783099 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.789s	user 0.002s	sys 0.000s
I20260812 06:37:21.801746 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.808s	user 0.065s	sys 0.003s
I20260812 06:37:22.594236 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.792s	user 0.066s	sys 0.000s
I20260812 06:37:23.332396 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.738s	user 0.058s	sys 0.000s
I20260812 06:37:24.105320 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.773s	user 0.054s	sys 0.008s
I20260812 06:37:25.437901 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.332s	user 0.057s	sys 0.000s
W20260812 06:37:26.155331 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.717s	user 0.001s	sys 0.000s
I20260812 06:37:27.159477 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.721s	user 0.067s	sys 0.000s
W20260812 06:37:27.880440 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.721s	user 0.001s	sys 0.000s
I20260812 06:37:28.784947 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.625s	user 0.058s	sys 0.004s
I20260812 06:37:28.916313 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1042, attempt_no=0}) took 1050 ms. Trace:
I20260812 06:37:28.916394 11856 rpcz_store.cc:276] 0812 06:37:27.866172 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:27.866218 (+    46us) service_pool.cc:224] Handling call
0812 06:37:28.916303 (+1050085us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:27.866767 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:27.866866 (+    99us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:27.866870 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:27.866872 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:27.870333 (+  3461us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:27.870344 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:27.870347 (+     3us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:27.874668 (+  4321us) tablet.cc:701] Row locks acquired
0812 06:37:27.874670 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:27.874719 (+    49us) write_op.cc:270] Start()
0812 06:37:27.874746 (+    27us) write_op.cc:276] Timestamp: P: 1786516647874706 usec, L: 0
0812 06:37:27.874748 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:27.874951 (+   203us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:27.875604 (+   653us) op_driver.cc:464] REPLICATION: finished
0812 06:37:27.875672 (+    68us) write_op.cc:301] APPLY: starting
0812 06:37:27.875684 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:28.340472 (+464788us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:28.340487 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:28.914702 (+574215us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:28.915040 (+   338us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:28.915045 (+     5us) write_op.cc:312] APPLY: finished
0812 06:37:28.915746 (+   701us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:28.915913 (+   167us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:28.916183 (+   270us) write_op.cc:454] Released schema lock
0812 06:37:28.916231 (+    48us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":32,"cfile_cache_hit":4000,"cfile_cache_hit_bytes":19254000,"num_ops":1000,"prepare.queue_time_us":181,"prepare.run_cpu_time_us":8242,"prepare.run_wall_time_us":8243,"replication_time_us":834,"spinlock_wait_cycles":599296,"thread_start_us":162,"threads_started":2,"wal-append.queue_time_us":264}]]}
I20260812 06:37:29.597018 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.812s	user 0.060s	sys 0.001s
I20260812 06:37:30.912791 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.315s	user 0.066s	sys 0.000s
I20260812 06:37:31.767676 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.855s	user 0.055s	sys 0.007s
W20260812 06:37:32.701260 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.933s	user 0.001s	sys 0.000s
I20260812 06:37:33.735847 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.968s	user 0.064s	sys 0.000s
W20260812 06:37:34.407773 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.672s	user 0.001s	sys 0.000s
I20260812 06:37:35.397433 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1049, attempt_no=0}) took 1004 ms. Trace:
I20260812 06:37:35.397516 11856 rpcz_store.cc:276] 0812 06:37:34.392949 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:34.392998 (+    49us) service_pool.cc:224] Handling call
0812 06:37:35.397421 (+1004423us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:34.393558 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:34.393655 (+    97us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:34.393658 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:37:34.393660 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:34.397136 (+  3476us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:34.397145 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:34.397149 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:34.401533 (+  4384us) tablet.cc:701] Row locks acquired
0812 06:37:34.401535 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:34.401578 (+    43us) write_op.cc:270] Start()
0812 06:37:34.401603 (+    25us) write_op.cc:276] Timestamp: P: 1786516654401568 usec, L: 0
0812 06:37:34.401606 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:37:34.401791 (+   185us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:34.403228 (+  1437us) op_driver.cc:464] REPLICATION: finished
0812 06:37:34.403300 (+    72us) write_op.cc:301] APPLY: starting
0812 06:37:34.403312 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:34.882813 (+479501us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:34.882827 (+    14us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:35.395997 (+513170us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:35.396288 (+   291us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:35.396293 (+     5us) write_op.cc:312] APPLY: finished
0812 06:37:35.396979 (+   686us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:35.397047 (+    68us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:35.397299 (+   252us) write_op.cc:454] Released schema lock
0812 06:37:35.397347 (+    48us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":30,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19262212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":43,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":178,"prepare.run_cpu_time_us":8251,"prepare.run_wall_time_us":8770,"replication_time_us":1598,"spinlock_wait_cycles":566144,"thread_start_us":78,"threads_started":1}]]}
I20260812 06:37:35.497597 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.761s	user 0.058s	sys 0.004s
W20260812 06:37:36.134737 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.637s	user 0.001s	sys 0.000s
I20260812 06:37:37.144104 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1051, attempt_no=0}) took 1022 ms. Trace:
I20260812 06:37:37.144199 11856 rpcz_store.cc:276] 0812 06:37:36.121429 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:36.121478 (+    49us) service_pool.cc:224] Handling call
0812 06:37:37.144091 (+1022613us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:36.122027 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:36.122119 (+    92us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:36.122123 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:36.122124 (+     1us) tablet.cc:662] Decoding operations
0812 06:37:36.125919 (+  3795us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:36.125928 (+     9us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:36.125932 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:36.130713 (+  4781us) tablet.cc:701] Row locks acquired
0812 06:37:36.130716 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:36.130760 (+    44us) write_op.cc:270] Start()
0812 06:37:36.130786 (+    26us) write_op.cc:276] Timestamp: P: 1786516656130749 usec, L: 0
0812 06:37:36.130788 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:36.130984 (+   196us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:36.131614 (+   630us) op_driver.cc:464] REPLICATION: finished
0812 06:37:36.131845 (+   231us) write_op.cc:301] APPLY: starting
0812 06:37:36.131860 (+    15us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:36.602124 (+470264us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:36.602140 (+    16us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:37.142400 (+540260us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:37.142697 (+   297us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:37.142702 (+     5us) write_op.cc:312] APPLY: finished
0812 06:37:37.143467 (+   765us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:37.143722 (+   255us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:37.143971 (+   249us) write_op.cc:454] Released schema lock
0812 06:37:37.144017 (+    46us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":178,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19262212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":36,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":188,"prepare.run_cpu_time_us":8286,"prepare.run_wall_time_us":9016,"replication_time_us":806,"spinlock_wait_cycles":674944,"thread_start_us":171,"threads_started":2,"wal-append.queue_time_us":171}]]}
I20260812 06:37:37.259024 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.761s	user 0.066s	sys 0.000s
W20260812 06:37:38.088518 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.829s	user 0.001s	sys 0.000s
I20260812 06:37:39.178826 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.919s	user 0.065s	sys 0.000s
I20260812 06:37:39.944271 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.765s	user 0.058s	sys 0.000s
I20260812 06:37:41.071319 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1055, attempt_no=0}) took 1057 ms. Trace:
I20260812 06:37:41.071408 11856 rpcz_store.cc:276] 0812 06:37:40.013776 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:40.013823 (+    47us) service_pool.cc:224] Handling call
0812 06:37:41.071308 (+1057485us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:40.014408 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:40.014506 (+    98us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:40.014509 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:37:40.014511 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:40.018486 (+  3975us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:40.018496 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:40.018500 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:40.023604 (+  5104us) tablet.cc:701] Row locks acquired
0812 06:37:40.023607 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:37:40.023651 (+    44us) write_op.cc:270] Start()
0812 06:37:40.023677 (+    26us) write_op.cc:276] Timestamp: P: 1786516660023641 usec, L: 0
0812 06:37:40.023679 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:40.023905 (+   226us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:40.024506 (+   601us) op_driver.cc:464] REPLICATION: finished
0812 06:37:40.024577 (+    71us) write_op.cc:301] APPLY: starting
0812 06:37:40.024589 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:40.535719 (+511130us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:40.535734 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:41.069117 (+533383us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:41.069598 (+   481us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:41.069605 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:41.070691 (+  1086us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:41.070890 (+   199us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:41.071189 (+   299us) write_op.cc:454] Released schema lock
0812 06:37:41.071237 (+    48us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":26,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19262212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":34,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":190,"prepare.run_cpu_time_us":8750,"prepare.run_wall_time_us":9592,"replication_time_us":806,"spinlock_wait_cycles":584192,"thread_start_us":190,"threads_started":2,"wal-append.queue_time_us":288}]]}
I20260812 06:37:41.106118 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.162s	user 0.061s	sys 0.004s
I20260812 06:37:41.951774 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.845s	user 0.064s	sys 0.000s
I20260812 06:37:41.959255 11914 scanners.cc:360] slow scan reporting is disabled: set --show_slow_scans to enable
I20260812 06:37:42.094628 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1056, attempt_no=0}) took 1017 ms. Trace:
I20260812 06:37:42.094722 11856 rpcz_store.cc:276] 0812 06:37:41.077274 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:41.077320 (+    46us) service_pool.cc:224] Handling call
0812 06:37:42.094614 (+1017294us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:41.077877 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:41.077991 (+   114us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:41.077995 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:37:41.077997 (+     2us) tablet.cc:662] Decoding operations
0812 06:37:41.083859 (+  5862us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:41.083870 (+    11us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:41.083875 (+     5us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:41.091784 (+  7909us) tablet.cc:701] Row locks acquired
0812 06:37:41.091786 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:41.091836 (+    50us) write_op.cc:270] Start()
0812 06:37:41.091863 (+    27us) write_op.cc:276] Timestamp: P: 1786516661091824 usec, L: 0
0812 06:37:41.091866 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:37:41.092054 (+   188us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:41.092654 (+   600us) op_driver.cc:464] REPLICATION: finished
0812 06:37:41.092724 (+    70us) write_op.cc:301] APPLY: starting
0812 06:37:41.092737 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:41.550955 (+458218us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:41.550970 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:42.092425 (+541455us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:42.092903 (+   478us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:42.092910 (+     7us) write_op.cc:312] APPLY: finished
0812 06:37:42.094001 (+  1091us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:42.094196 (+   195us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:42.094462 (+   266us) write_op.cc:454] Released schema lock
0812 06:37:42.094524 (+    62us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":34,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19262212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":33,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":167,"prepare.run_cpu_time_us":13061,"prepare.run_wall_time_us":14243,"replication_time_us":767,"spinlock_wait_cycles":438784,"thread_start_us":183,"threads_started":2,"wal-append.queue_time_us":201}]]}
I20260812 06:37:42.822650 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.870s	user 0.068s	sys 0.000s
I20260812 06:37:44.226053 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.403s	user 0.069s	sys 0.000s
I20260812 06:37:45.136420 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.910s	user 0.069s	sys 0.000s
W20260812 06:37:45.762058 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.625s	user 0.000s	sys 0.000s
I20260812 06:37:46.894626 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.758s	user 0.069s	sys 0.000s
I20260812 06:37:47.759308 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.864s	user 0.065s	sys 0.000s
W20260812 06:37:48.546696 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.787s	user 0.000s	sys 0.000s
I20260812 06:37:49.615561 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.856s	user 0.061s	sys 0.003s
I20260812 06:37:50.534593 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.919s	user 0.064s	sys 0.004s
I20260812 06:37:51.460775 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.926s	user 0.068s	sys 0.004s
W20260812 06:37:52.095795 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.635s	user 0.000s	sys 0.000s
I20260812 06:37:53.282080 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.821s	user 0.068s	sys 0.000s
I20260812 06:37:54.199623 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.917s	user 0.065s	sys 0.000s
I20260812 06:37:54.981755 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1070, attempt_no=0}) took 1052 ms. Trace:
I20260812 06:37:54.981834 11856 rpcz_store.cc:276] 0812 06:37:53.929308 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:37:53.929347 (+    39us) service_pool.cc:224] Handling call
0812 06:37:54.981745 (+1052398us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:37:53.929889 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:37:53.929980 (+    91us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:37:53.929983 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:37:53.929984 (+     1us) tablet.cc:662] Decoding operations
0812 06:37:53.932809 (+  2825us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:37:53.932819 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:37:53.932822 (+     3us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:37:53.937396 (+  4574us) tablet.cc:701] Row locks acquired
0812 06:37:53.937398 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:37:53.937437 (+    39us) write_op.cc:270] Start()
0812 06:37:53.937459 (+    22us) write_op.cc:276] Timestamp: P: 1786516673937427 usec, L: 0
0812 06:37:53.937461 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:37:53.937620 (+   159us) log.cc:844] Serialized 52317 byte log entry
0812 06:37:53.938740 (+  1120us) op_driver.cc:464] REPLICATION: finished
0812 06:37:53.940664 (+  1924us) write_op.cc:301] APPLY: starting
0812 06:37:53.940677 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:37:54.456623 (+515946us) tablet.cc:1370] finished BulkCheckPresence
0812 06:37:54.456636 (+    13us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:37:54.980096 (+523460us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:37:54.980397 (+   301us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:37:54.980402 (+     5us) write_op.cc:312] APPLY: finished
0812 06:37:54.981169 (+   767us) log.cc:844] Serialized 8020 byte log entry
0812 06:37:54.981345 (+   176us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:37:54.981632 (+   287us) write_op.cc:454] Released schema lock
0812 06:37:54.981678 (+    46us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":1876,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19468212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":54,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":176,"prepare.run_cpu_time_us":7747,"prepare.run_wall_time_us":7790,"replication_time_us":1256,"spinlock_wait_cycles":1148032,"thread_start_us":162,"threads_started":2,"wal-append.queue_time_us":173}]]}
I20260812 06:37:55.080412 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.880s	user 0.055s	sys 0.004s
I20260812 06:37:55.909783 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.829s	user 0.060s	sys 0.000s
I20260812 06:37:57.288702 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.379s	user 0.071s	sys 0.000s
I20260812 06:37:58.754348 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.465s	user 0.062s	sys 0.000s
W20260812 06:37:59.397939 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.643s	user 0.000s	sys 0.001s
I20260812 06:38:00.578745 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.824s	user 0.060s	sys 0.004s
I20260812 06:38:01.656988 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.078s	user 0.066s	sys 0.000s
I20260812 06:38:03.262827 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.606s	user 0.060s	sys 0.000s
I20260812 06:38:04.208642 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.945s	user 0.058s	sys 0.000s
W20260812 06:38:04.807621 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.599s	user 0.002s	sys 0.000s
I20260812 06:38:05.721097 11610 maintenance_manager.cc:419] P af411fb8b0654e64b16a87975c8a12c5: Scheduling FlushMRSOp(00000000000000000000000000000000): perf score=0.033889
I20260812 06:38:05.730388 11607 maintenance_manager.cc:643] P af411fb8b0654e64b16a87975c8a12c5: FlushMRSOp(00000000000000000000000000000000) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":6519,"cfile_init":1,"dirs.queue_time_us":185,"dirs.run_cpu_time_us":158,"dirs.run_wall_time_us":999,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":362,"lbm_writes_lt_1ms":27,"peak_mem_usage":0,"rows_written":5,"thread_start_us":188,"threads_started":2,"wal-append.queue_time_us":151}
I20260812 06:38:05.730893 11610 maintenance_manager.cc:419] P af411fb8b0654e64b16a87975c8a12c5: Scheduling UndoDeltaBlockGCOp(00000000000000000000000000000000): 391 bytes on disk
I20260812 06:38:05.731338 11607 maintenance_manager.cc:643] P af411fb8b0654e64b16a87975c8a12c5: UndoDeltaBlockGCOp(00000000000000000000000000000000) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:38:05.795868 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1082, attempt_no=0}) took 1003 ms. Trace:
I20260812 06:38:05.795964 11856 rpcz_store.cc:276] 0812 06:38:04.791939 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:38:04.791984 (+    45us) service_pool.cc:224] Handling call
0812 06:38:05.795855 (+1003871us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:38:04.792550 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:38:04.792652 (+   102us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:38:04.792655 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:38:04.792657 (+     2us) tablet.cc:662] Decoding operations
0812 06:38:04.796567 (+  3910us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:38:04.796577 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:38:04.796580 (+     3us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:38:04.801833 (+  5253us) tablet.cc:701] Row locks acquired
0812 06:38:04.801836 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:38:04.801882 (+    46us) write_op.cc:270] Start()
0812 06:38:04.801908 (+    26us) write_op.cc:276] Timestamp: P: 1786516684801871 usec, L: 0
0812 06:38:04.801910 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:38:04.802097 (+   187us) log.cc:844] Serialized 52317 byte log entry
0812 06:38:04.802766 (+   669us) op_driver.cc:464] REPLICATION: finished
0812 06:38:04.802867 (+   101us) write_op.cc:301] APPLY: starting
0812 06:38:04.802880 (+    13us) tablet.cc:1367] starting BulkCheckPresence
0812 06:38:05.286380 (+483500us) tablet.cc:1370] finished BulkCheckPresence
0812 06:38:05.286393 (+    13us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:38:05.793819 (+507426us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:38:05.794273 (+   454us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:38:05.794279 (+     6us) write_op.cc:312] APPLY: finished
0812 06:38:05.795368 (+  1089us) log.cc:844] Serialized 8020 byte log entry
0812 06:38:05.795436 (+    68us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:38:05.795718 (+   282us) write_op.cc:454] Released schema lock
0812 06:38:05.795781 (+    63us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":33,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19468212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":38,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":170,"prepare.run_cpu_time_us":8709,"prepare.run_wall_time_us":10102,"replication_time_us":836,"spinlock_wait_cycles":618112,"thread_start_us":77,"threads_started":1}]]}
I20260812 06:38:05.953469 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.744s	user 0.060s	sys 0.000s
I20260812 06:38:06.975898 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.022s	user 0.059s	sys 0.004s
W20260812 06:38:07.550216 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.574s	user 0.001s	sys 0.000s
I20260812 06:38:08.797556 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.821s	user 0.067s	sys 0.004s
I20260812 06:38:10.524907 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.727s	user 0.070s	sys 0.000s
I20260812 06:38:12.253443 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1089, attempt_no=0}) took 1268 ms. Trace:
I20260812 06:38:12.253576 11856 rpcz_store.cc:276] 0812 06:38:10.984497 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:38:10.984560 (+    63us) service_pool.cc:224] Handling call
0812 06:38:12.253431 (+1268871us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:38:10.985180 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:38:10.985277 (+    97us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:38:10.985281 (+     4us) write_op.cc:435] Acquired schema lock
0812 06:38:10.985283 (+     2us) tablet.cc:662] Decoding operations
0812 06:38:10.989064 (+  3781us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:38:10.989074 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:38:10.989078 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:38:10.993823 (+  4745us) tablet.cc:701] Row locks acquired
0812 06:38:10.993825 (+     2us) write_op.cc:260] PREPARE: finished
0812 06:38:10.993869 (+    44us) write_op.cc:270] Start()
0812 06:38:10.993894 (+    25us) write_op.cc:276] Timestamp: P: 1786516690993858 usec, L: 0
0812 06:38:10.993897 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:38:10.994232 (+   335us) log.cc:844] Serialized 52317 byte log entry
0812 06:38:10.994841 (+   609us) op_driver.cc:464] REPLICATION: finished
0812 06:38:10.994906 (+    65us) write_op.cc:301] APPLY: starting
0812 06:38:10.994936 (+    30us) tablet.cc:1367] starting BulkCheckPresence
0812 06:38:11.602795 (+607859us) tablet.cc:1370] finished BulkCheckPresence
0812 06:38:11.602820 (+    25us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:38:12.251807 (+648987us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:38:12.252110 (+   303us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:38:12.252114 (+     4us) write_op.cc:312] APPLY: finished
0812 06:38:12.252875 (+   761us) log.cc:844] Serialized 8020 byte log entry
0812 06:38:12.253045 (+   170us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:38:12.253319 (+   274us) write_op.cc:454] Released schema lock
0812 06:38:12.253367 (+    48us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":34,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19468212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":54,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":193,"prepare.run_cpu_time_us":8244,"prepare.run_wall_time_us":9120,"replication_time_us":923,"spinlock_wait_cycles":436736,"thread_start_us":161,"threads_started":2,"wal-append.queue_time_us":158}]]}
I20260812 06:38:12.387280 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.862s	user 0.065s	sys 0.000s
I20260812 06:38:13.289263 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1090, attempt_no=0}) took 1031 ms. Trace:
I20260812 06:38:13.289353 11856 rpcz_store.cc:276] 0812 06:38:12.258179 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:38:12.258219 (+    40us) service_pool.cc:224] Handling call
0812 06:38:13.289252 (+1031033us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:38:12.258906 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:38:12.259038 (+   132us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:38:12.259041 (+     3us) write_op.cc:435] Acquired schema lock
0812 06:38:12.259043 (+     2us) tablet.cc:662] Decoding operations
0812 06:38:12.262846 (+  3803us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:38:12.262856 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:38:12.262860 (+     4us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:38:12.267937 (+  5077us) tablet.cc:701] Row locks acquired
0812 06:38:12.267940 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:38:12.267983 (+    43us) write_op.cc:270] Start()
0812 06:38:12.268009 (+    26us) write_op.cc:276] Timestamp: P: 1786516692267972 usec, L: 0
0812 06:38:12.268011 (+     2us) op_driver.cc:348] REPLICATION: starting
0812 06:38:12.268214 (+   203us) log.cc:844] Serialized 52317 byte log entry
0812 06:38:12.271145 (+  2931us) op_driver.cc:464] REPLICATION: finished
0812 06:38:12.271214 (+    69us) write_op.cc:301] APPLY: starting
0812 06:38:12.271225 (+    11us) tablet.cc:1367] starting BulkCheckPresence
0812 06:38:12.781260 (+510035us) tablet.cc:1370] finished BulkCheckPresence
0812 06:38:12.781275 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:38:13.287231 (+505956us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:38:13.287690 (+   459us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:38:13.287697 (+     7us) write_op.cc:312] APPLY: finished
0812 06:38:13.288681 (+   984us) log.cc:844] Serialized 8020 byte log entry
0812 06:38:13.288860 (+   179us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:38:13.289123 (+   263us) write_op.cc:454] Released schema lock
0812 06:38:13.289181 (+    58us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":25,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19468212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":33,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":165,"prepare.run_cpu_time_us":8660,"prepare.run_wall_time_us":9971,"replication_time_us":3053,"spinlock_wait_cycles":788736,"thread_start_us":163,"threads_started":2,"wal-append.queue_time_us":180}]]}
I20260812 06:38:13.336951 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.949s	user 0.063s	sys 0.000s
W20260812 06:38:14.051288 11912 scanner-internal.cc:458] Time spent opening tablet: real 0.714s	user 0.000s	sys 0.000s
I20260812 06:38:15.358727 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 2.021s	user 0.066s	sys 0.000s
I20260812 06:38:16.295687 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.937s	user 0.062s	sys 0.000s
I20260812 06:38:18.158021 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.862s	user 0.067s	sys 0.000s
I20260812 06:38:19.157378 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.999s	user 0.065s	sys 0.003s
I20260812 06:38:20.776815 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.619s	user 0.066s	sys 0.004s
I20260812 06:38:21.535632 11856 rpcz_store.cc:275] Call kudu.tserver.TabletServerService.Write from 127.0.0.1:34730 (ReqId={client: d112e64eebc44933990f9d5c23b9f37e, seq_no=1099, attempt_no=0}) took 1036 ms. Trace:
I20260812 06:38:21.535715 11856 rpcz_store.cc:276] 0812 06:38:20.499073 (+     0us) service_pool.cc:167] Inserting onto call queue
0812 06:38:20.499122 (+    49us) service_pool.cc:224] Handling call
0812 06:38:21.535622 (+1036500us) inbound_call.cc:177] Queueing success response
Related trace 'op':
0812 06:38:20.499798 (+     0us) write_op.cc:183] PREPARE: starting on tablet 60ab298c91334b429b0400ade230cc6f
0812 06:38:20.499911 (+   113us) write_op.cc:432] Acquiring schema lock in shared mode
0812 06:38:20.499916 (+     5us) write_op.cc:435] Acquired schema lock
0812 06:38:20.499917 (+     1us) tablet.cc:662] Decoding operations
0812 06:38:20.504973 (+  5056us) write_op.cc:620] Acquiring the partition lock for write op
0812 06:38:20.504983 (+    10us) write_op.cc:641] Partition lock acquired for write op
0812 06:38:20.504988 (+     5us) tablet.cc:685] Acquiring locks for 1000 operations
0812 06:38:20.512239 (+  7251us) tablet.cc:701] Row locks acquired
0812 06:38:20.512242 (+     3us) write_op.cc:260] PREPARE: finished
0812 06:38:20.512287 (+    45us) write_op.cc:270] Start()
0812 06:38:20.512314 (+    27us) write_op.cc:276] Timestamp: P: 1786516700512275 usec, L: 0
0812 06:38:20.512317 (+     3us) op_driver.cc:348] REPLICATION: starting
0812 06:38:20.512505 (+   188us) log.cc:844] Serialized 52317 byte log entry
0812 06:38:20.516571 (+  4066us) op_driver.cc:464] REPLICATION: finished
0812 06:38:20.516659 (+    88us) write_op.cc:301] APPLY: starting
0812 06:38:20.516671 (+    12us) tablet.cc:1367] starting BulkCheckPresence
0812 06:38:21.001321 (+484650us) tablet.cc:1370] finished BulkCheckPresence
0812 06:38:21.001336 (+    15us) tablet.cc:1372] starting ApplyRowOperation cycle
0812 06:38:21.534028 (+532692us) tablet.cc:1383] finished ApplyRowOperation cycle
0812 06:38:21.534338 (+   310us) tablet_metrics.cc:581] ProbeStats: bloom_lookups=2000,key_file_lookups=2000,delta_file_lookups=0,mrs_lookups=0
0812 06:38:21.534344 (+     6us) write_op.cc:312] APPLY: finished
0812 06:38:21.535088 (+   744us) log.cc:844] Serialized 8020 byte log entry
0812 06:38:21.535245 (+   157us) write_op.cc:489] Releasing partition, row and schema locks
0812 06:38:21.535514 (+   269us) write_op.cc:454] Released schema lock
0812 06:38:21.535559 (+    45us) write_op.cc:341] FINISH: Updating metrics
Metrics: {"child_traces":[["op",{"apply.queue_time_us":35,"cfile_cache_hit":4002,"cfile_cache_hit_bytes":19468212,"cfile_cache_miss":1,"cfile_cache_miss_bytes":4106,"lbm_read_time_us":30,"lbm_reads_lt_1ms":1,"num_ops":1000,"prepare.queue_time_us":273,"prepare.run_cpu_time_us":12770,"prepare.run_wall_time_us":13266,"replication_time_us":4122,"spinlock_wait_cycles":1170688,"thread_start_us":176,"threads_started":2,"wal-append.queue_time_us":162}]]}
I20260812 06:38:21.801774 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 1.025s	user 0.070s	sys 0.001s
I20260812 06:38:22.588864 11912 update_scan_delta_compact-test.cc:265] Time spent Scan: real 0.787s	user 0.057s	sys 0.000s
I20260812 06:38:23.001808 11909 update_scan_delta_compact-test.cc:244] Time spent Update: real 101.046s	user 3.200s	sys 0.142s
I20260812 06:38:23.002209 11584 tablet_server.cc:179] TabletServer@127.11.80.1:0 shutting down...
I20260812 06:38:23.007104 11584 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:38:23.007606 11584 tablet_replica.cc:333] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6: stopping tablet replica
I20260812 06:38:23.007817 11584 raft_consensus.cc:2243] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:38:23.007993 11584 raft_consensus.cc:2272] T 60ab298c91334b429b0400ade230cc6f P 0ad813103238463fb17e46a8f942f3b6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:38:23.031164 11584 tablet_server.cc:196] TabletServer@127.11.80.1:0 shutdown complete.
I20260812 06:38:23.034879 11584 master.cc:562] Master@127.11.80.62:33305 shutting down...
I20260812 06:38:23.038672 11584 raft_consensus.cc:2243] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:38:23.038806 11584 raft_consensus.cc:2272] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:38:23.038877 11584 tablet_replica.cc:333] T 00000000000000000000000000000000 P af411fb8b0654e64b16a87975c8a12c5: stopping tablet replica
I20260812 06:38:23.053653 11584 master.cc:584] Master@127.11.80.62:33305 shutdown complete.
[       OK ] UpdateScanDeltaCompactionTest.TestAll (139456 ms)
[----------] 1 test from UpdateScanDeltaCompactionTest (139567 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test suite ran. (139567 ms total)
[  PASSED  ] 1 test.
I20260812 06:38:23.598856 11584 logging.cc:436] LogThrottler /workspace/apache/dev/local/kudu/src/kudu/tserver/scanners.cc:360: suppressed but not reported on 12415 messages since previous log ~41 seconds ago
