Issue Summary

WT_CONNECTION::set_timestamp emits verbose messages from inside the txn_global->rwlock write-locked critical section. The verbose path calls the application's handle_message event handler synchronously on the calling thread, so any latency in the application's logging sink is absorbed while the global timestamp lock is held. Every reader of the global timestamps – snapshot acquisition, checkpoint transaction setup, the pinned-timestamp scan – blocks behind it.

Context

• The write lock is taken in _wt_txn_global_set_timestamp and released after the assignments. The verbose calls for the stable timestamp, oldest timestamp, and stable disaggregated schema epoch all sit between those two points, as does the pinned-timestamp message in _wt_txn_update_pinned_timestamp.
• The call chain is fully synchronous: _wt_verbose_timestamp > wt_verbose -> wt_verbose_worker -> _eventv -> handler>handle_message. There is no buffering or handoff to another thread.
• These are DEBUG_1 messages, so at default verbosity they are never generated and the cost is zero. The defect is only reachable when timestamp verbosity is raised, which is typically done while investigating an unrelated problem.
• Amplifier: connection-level API calls run on conn->default_session, which is flagged WT_SESSION_INTERNAL, so every _wt_scr_alloc serialises on the single per-connection scratch_lock. Under json_output=[message], _eventv allocates two scratch buffers per message, so concurrent verbose traffic from other threads contends with the lock holder.

Field evidence

Observed on a disaggregated-storage cluster (HELP-100780) with wtTimestamp raised to debug level 1: a single set_timestamp call took over 1.5 s against roughly 1 ms when healthy. Two independent readings of the same log excerpts:

• Each WiredTiger JSON message carries the ts_sec/ts_usec pair recorded by __eventv at format time, which the embedder can compare against its own receive timestamp. On a healthy node the two agree; during the stall they diverged by 140-616 ms. The delay is after WiredTiger finished formatting the string, i.e. in the handler.
• Two timestamps supplied in one set_timestamp call are stored a few atomic operations apart, yet their verbose messages were 200 ms apart. That gap cannot be the timestamp work.

Proposed Solution

• Move the verbose calls out of the locked regions in _wt_txn_global_set_timestamp and _wt_txn_update_pinned_timestamp: record which timestamps were actually updated and their values into locals inside the critical section, then emit the messages after the unlock.
• Audit other verbose and message calls made while holding txn_global->rwlock for the same pattern.

What this ticket does not fix

The embedder's event handler is still called synchronously on the thread making the API call, so set_timestamp remains as slow as the handler. In the HELP-100780 incident MongoDB holds _oplogManagementMutex across the set_timestamp call and takes the same mutex to generate heartbeats, so the heartbeat stall, the election, and the node restart would all still occur with this ticket fixed.

Addressing that requires the embedder's logging to not block a storage-engine API call. That is outside WiredTiger's control – WiredTiger calls whatever handler the embedder installs. Raised with the server team on HELP-100780 for them to assess and ticket if they judge a redesign is warranted.

A separate question worth considering on the WiredTiger side: whether it is acceptable for any verbose call to be able to block an API call for an unbounded time, or whether WiredTiger should bound its exposure to a slow handler. Not in scope here.

Acceptance Criteria

• No verbose or message call is issued while txn_global->rwlock is held.
• Readers of the global timestamps are not blocked by event-handler latency.
• The same set of messages, with the same values, is still emitted.

Related Files

• src/txn/txn_timestamp.c – _wt_txn_global_set_timestamp, _wt_txn_update_pinned_timestamp
• src/support/err.c – __eventv, the synchronous handler dispatch
• src/support/scratch.c – __wt_scr_alloc_func, the shared-session scratch lock