Skip to content

Commit 8bb4491

Browse files
committed
fix: scope query counting to the measuring thread
The synchronous benchmark subscribed to sql.active_record process-wide while a worker ran on its own thread, so whatever the worker polled during the window landed in the count. Stability across runs made that look deterministic when it was only consistent. Counting is now scoped to the thread being measured, and the caller and the worker turn are measured separately rather than by watching both at once, because a poll belongs to no particular call. This corrects a claim made in the previous commit. The caller of a synchronous call costs 49 queries, exactly what was documented before; the 53 reported earlier was four stray polls. The message turn drift is real and stands at 26 against a documented 29, since that measurement always ran on the measuring thread with nothing else alive. The script also reports the total a synchronous call costs the database, 75, which was never recorded.
1 parent 7b034ea commit 8bb4491

3 files changed

Lines changed: 40 additions & 22 deletions

File tree

CHANGELOG.md

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -8,9 +8,12 @@
88
prints the refusal and the setting that grants access, and exits 1.
99
- Measure the query count for a synchronous call. `benchmark/query_count.rb`
1010
only measured a worker turn, so the documented synchronous number had no
11-
script behind it and had drifted: a message turn costs 26 queries rather than
12-
the documented 29, and a synchronous call 53 rather than 49. Both are
13-
deterministic and now reported by the same script.
11+
script behind it. It reports three now: a message turn costs 26 queries
12+
rather than the documented 29, the caller of a synchronous call costs 49, and
13+
a synchronous call in total costs 75, being a caller plus the turn it waits
14+
on. Counting is scoped to the measuring thread, since a worker loop polls
15+
whether or not a call is in flight and a process-wide count folds those polls
16+
into the result.
1417

1518
- Run payload broadcast blocks against the actor instance, like every other
1619
block in the actor DSL. `self` was the actor class, so an actor instance

benchmark/support.rb

Lines changed: 23 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -291,45 +291,55 @@ def component_delivery
291291

292292
# @rbs () -> void
293293
def query_count
294-
message_turn_query_count
295-
synchronous_query_count
294+
turn = message_turn_query_count
295+
caller_queries = synchronous_caller_query_count
296+
puts "database queries: #{turn} for 1 message turn"
297+
puts "database queries: #{caller_queries} for the caller of 1 synchronous call"
298+
puts "database queries: #{caller_queries + turn} for 1 synchronous call, caller plus the turn it waits on"
296299
end
297300

298301
private
299302

300-
# @rbs () -> void
303+
# Runs the turn on the measuring thread, so nothing else can contribute.
304+
# @rbs () -> Integer
301305
def message_turn_query_count
302306
CounterActor.ref("queries").async(:increment)
303307
worker = SolidObjects::Worker.new
304-
processed = nil
305-
queries = count_queries { processed = worker.run_once }
306-
puts "database queries: #{queries} for #{processed} message"
308+
count_queries { worker.run_once }
307309
ensure
308310
worker&.stop
309311
end
310312

311313
# A synchronous call also registers or heartbeats the caller process,
312-
# claims the activation, and observes the result, so it costs more than the
313-
# worker turn it contains. The first call is discarded because it pays for
314-
# activation and caller registration that a steady-state call does not.
315-
# @rbs () -> void
316-
def synchronous_query_count
314+
# claims the activation, and observes the result, so the caller costs more
315+
# than the turn it waits on. Only the caller thread is counted; the worker
316+
# runs on its own thread and its turn is measured separately, because a
317+
# worker loop also polls and those polls belong to no particular call. The
318+
# first call is discarded because it pays for activation and caller
319+
# registration that a steady-state call does not.
320+
# @rbs () -> Integer
321+
def synchronous_caller_query_count
317322
reference = CounterActor.ref("sync-queries")
318323
worker = SolidObjects::Worker.new
319324
runner = Thread.new { worker.run }
320325
reference.sync(:increment)
321-
queries = count_queries { reference.sync(:increment) }
322-
puts "database queries: #{queries} for 1 synchronous call"
326+
count_queries { reference.sync(:increment) }
323327
ensure
324328
worker&.request_shutdown
325329
runner&.join(5)
326330
worker&.stop
327331
end
328332

333+
# Subscriptions are process-wide and notifications run on the thread that
334+
# issued the query, so counting is scoped to the measuring thread. Without
335+
# that, a worker polling in the background inflates the count by however
336+
# many times it happened to poll during the window.
329337
# @rbs () { () -> untyped } -> Integer
330338
def count_queries
339+
measuring = Thread.current
331340
queries = 0
332341
subscriber = ActiveSupport::Notifications.subscribe("sql.active_record") do |event|
342+
next unless Thread.current.equal?(measuring)
333343
next if %w[SCHEMA TRANSACTION].include?(event.payload[:name])
334344
next if event.payload[:cached]
335345

docs/benchmarks.md

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -43,17 +43,22 @@ scenario used four worker threads.
4343

4444
Query counts are a property of the code rather than the host, so they are
4545
tracked separately. Re-measured 2026-08-10 against 0.10.0 on SQLite with
46-
`bundle exec ruby benchmark/query_count.rb`, which reports both and is
47-
deterministic across runs:
46+
`bundle exec ruby benchmark/query_count.rb`, which is deterministic across runs:
4847

4948
| Scenario | Queries |
5049
| --- | ---: |
5150
| One message turn | 26 |
52-
| One synchronous call | 53 |
51+
| The caller of one synchronous call | 49 |
52+
| One synchronous call, caller plus the turn it waits on | 75 |
5353

54-
Both numbers moved since they were first recorded, in opposite directions: a
55-
worker turn fell from 29 and a synchronous call rose from 49. The synchronous
56-
count had no script behind it until now, which is why it drifted unnoticed.
54+
A worker turn fell from the 29 recorded earlier. The caller count is unchanged
55+
at 49, and the combined figure is new: a synchronous call is a caller and a
56+
worker turn, and only the sum says what the database actually serves.
57+
58+
Counting is scoped to the measuring thread. A worker loop polls whether or not
59+
a call is in flight, so a process-wide count folds however many polls happened
60+
to land inside the window into the result. That is also why the caller and the
61+
turn are measured separately rather than by watching both threads at once.
5762

5863
A synchronous call costs far more queries than a worker turn because the caller
5964
also registers or heartbeats its caller process, claims the activation, and

0 commit comments

Comments
 (0)