Skip to content

log: make write timeout per waiter instead of shared - #49

Open
bb7133 wants to merge 1 commit into
pingcap:masterfrom
bb7133:fix-timeout-per-waiter
Open

bb7133 wants to merge 1 commit into
pingcap:masterfrom
bb7133:fix-timeout-per-waiter

Conversation

@bb7133

@bb7133 bb7133 commented Oct 19, 2026

Copy link
Copy Markdown
Member

What problem does this PR solve?

lockWithTimeoutWrapper counts timeout ticks from a single time.Ticker shared by all callers. Each tick is received by only one waiting goroutine, so when N goroutines queue behind a stuck write, each of them needs timeout ticks of its own and actually waits about timeout * N seconds before panicking (panic action) or discarding (discard action). Waiters already inside the loop also don't see the timedOut flag, so they are released one per second.

Reproduced with TiDB master + enterprise audit log, [log] timeout=3, timeout-action="discard", audit log pointed at a FIFO whose reader was stopped, 32 concurrent connections: the first connection was released after ~64s and all of them only after ~95s (≈ 3s × 32); new connections were blocked for the same time. The main TiDB log uses the same wrapper, so it is affected too.

What changed and how does it work?

  • Each getLockOrBlock call first tries the lock without blocking, then waits on its own time.NewTimer(timeout). The wait is bounded by timeout no matter how many goroutines are waiting.
  • Remove the shared ticker (which was also never stopped).
  • Add TestTimeoutNotScaledByWaiters: 8 goroutines queue behind a stuck write with timeout=1, for both discard and panic, and must all return within 3s. On the old code this takes 8s and fails.

Regression with the same TiDB setup (32 connections, sink stuck for 40s, discard): 1.12M queries completed during the stall, max query latency 3.0s, no panic, audit writes resumed after the reader continued. With panic, TiDB still panics with Timeout of 3s when trying to write log.

Check List

Tests

  • Unit test
go test ./...
go test -race -count=5 -run Timeout .

🤖 Generated with Claude Code

lockWithTimeoutWrapper counted timeout ticks from one ticker shared by
all waiters. Each tick is delivered to only one waiter, so with N
callers queued behind a stuck write every caller waited about
timeout * N seconds before panicking or discarding. Give every call its
own timer so the wait is bounded by timeout regardless of how many
goroutines are waiting.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

@expxiaoli expxiaoli left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM. One non-blocking suggestion: please add a reference to the related GitHub issue in the PR description so the problem and its context are easier to trace.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants