The throughput doubled and the tail got worse

# Self-authored for the EML case corpus (no external origin). The batch size was
# raised from 10 to 100. Throughput went from 166 to 416 items a second. What a
# single request experiences is computed below.
#
# Batching is correct and the change was made for good reasons, with a
# before-and-after measurement to back it. Each batch carries a fixed 40 ms of
# overhead - one round trip, one transaction, one index update - and that cost
# is paid once whether the batch holds 10 rows or 100. Amortising a fixed cost
# over more work is the oldest optimisation there is, the benchmark confirmed
# it, and the confirmation was honest: throughput really did go up 2.5 times.
#
# Throughput is items per second, measured across the batch. Latency is a
# property of one request, measured from when it arrived. Batching moves cost
# from the first quantity to the second: it makes the shared overhead smaller
# per item and makes every item wait for the whole batch.
#
# Both numbers are real. Only one of them was on the dashboard.

40 => fixed_ms_per_batch
2 => ms_per_item
200 => arrivals_per_second

# [label, batch size]
[["no batching", 1], ["before", 10], ["after", 100]] => configs

"each batch costs " + str(fixed_ms_per_batch) + " ms fixed plus " + str(ms_per_item) + " ms per item" ^0
"requests arrive at " + str(arrivals_per_second) + " per second" ^0
"" ^0

# ---- what the benchmark measured: a saturated queue ----
#
# Under saturation there is always a full batch waiting, so nothing waits to be
# filled. This is the regime the benchmark ran in and every number it produced
# is correct for that regime.

"saturated benchmark - a full batch is always ready" ^0
"config          batch   ms per batch   items/sec   ms per item   request latency" ^0
for c in configs:
    fixed_ms_per_batch + (ms_per_item * c[1]) => batch_ms
    int(c[1] * 1000 / batch_ms) => throughput
    int(batch_ms * 100 / c[1]) => per_item_centims
    "  " + c[0] + "    " + str(c[1]) + "        " + str(batch_ms) + "            " + str(throughput) + "         " + str(per_item_centims) + " centims        " + str(batch_ms) ^0
"" ^0
"  throughput and cost per item both improve with batch size" ^0
"  request latency gets worse with batch size, in the same table" ^0
"" ^0

# ---- what production runs at ----
#
# 200 arrivals a second. A batch of 100 takes half a second to fill. The first
# request into a batch waits for the other 99 to show up, then waits for the
# batch to run.

"production at " + str(arrivals_per_second) + " arrivals per second" ^0
"config          batch   fill time   first-in waits   last-in waits   mean wait" ^0
for c in configs:
    fixed_ms_per_batch + (ms_per_item * c[1]) => batch_ms
    int(c[1] * 1000 / arrivals_per_second) => fill_ms
    fill_ms + batch_ms => first_in
    batch_ms => last_in
    int(fill_ms / 2) + batch_ms => mean_wait
    "  " + c[0] + "    " + str(c[1]) + "       " + str(fill_ms) + "          " + str(first_in) + "             " + str(last_in) + "            " + str(mean_wait) ^0
"" ^0

# ---- the two numbers side by side ----

fixed_ms_per_batch + (ms_per_item * 10) => before_batch_ms
fixed_ms_per_batch + (ms_per_item * 100) => after_batch_ms
int(10 * 1000 / before_batch_ms) => before_throughput
int(100 * 1000 / after_batch_ms) => after_throughput
int(10 * 1000 / arrivals_per_second) + before_batch_ms => before_first_in
int(100 * 1000 / arrivals_per_second) + after_batch_ms => after_first_in

"throughput  : " + str(before_throughput) + " -> " + str(after_throughput) + " items/sec, better by " + str(int(after_throughput * 100 / before_throughput)) + " hundredths" ^0
"worst wait  : " + str(before_first_in) + " -> " + str(after_first_in) + " ms, worse by " + str(int(after_first_in * 100 / before_first_in)) + " hundredths" ^0
"" ^0
"at " + str(arrivals_per_second) + " arrivals a second, " + str(before_throughput) + " items/sec was already enough" ^0
"the capacity that was bought was not short, and the wait that was sold was real" ^0
"" ^0

# ---- which quantity was instrumented ----
#
# Service time is how long the work took. Sojourn time is how long the
# requester waited. They are the same number only when nothing queues.

"service time vs sojourn time" ^0
"  service time  : time inside the batch call            -> " + str(after_batch_ms) + " ms" ^0
"  fill time     : time waiting for the batch to fill    -> " + str(int(100 * 1000 / arrivals_per_second)) + " ms" ^0
"  sojourn time  : what the caller experiences           -> " + str(after_first_in) + " ms" ^0
"  the timer was started when the batch call began" ^0
"  so it measured " + str(after_batch_ms) + " of the " + str(after_first_in) + " ms the caller waited" ^0
"  it was not reporting a wrong number, it was reporting a different one" ^0
"" ^0

# ---- the control ----
#
# If batching were simply a mistake, throughput would not have improved. It did,
# by exactly what the benchmark said. The change bought real capacity; the
# question is only whether capacity was the scarce thing.

"control - the quantity the change genuinely improved" ^0
0 => configs_measured
for c in configs:
    fixed_ms_per_batch + (ms_per_item * c[1]) => batch_ms
    int(c[1] * 1000 / batch_ms) => throughput
    configs_measured + 1 => configs_measured
    "  batch " + str(c[1]) + ": " + str(throughput) + " items/sec sustained" ^0
"  configs measured: " + str(configs_measured) + ", and throughput rises in every step" ^0
"  the benchmark was right, repeatable, and about the wrong axis" ^0
"" ^0

# ---- the null control ----
#
# Arrivals fast enough to fill a batch of 100 instantly. Fill time goes to
# zero and the sojourn time collapses onto the service time. The defect is not
# batching; it is a batch size chosen without reference to the arrival rate.

10000 => fast_arrivals
"null control - the same batch of 100 at " + str(fast_arrivals) + " arrivals per second" ^0
int(100 * 1000 / fast_arrivals) => fast_fill
"  fill time     : " + str(fast_fill) + " ms" ^0
"  first-in waits: " + str(fast_fill + after_batch_ms) + " ms" ^0
"  at " + str(arrivals_per_second) + " arrivals it was " + str(after_first_in) + " ms" ^0
"  same batch size, same code, same overhead constants" ^0
"  what changed is only how long 100 requests take to exist" ^0
"" ^0

# ---- the rule ----

"batch size trades one axis against the other, always in the same direction" ^0
"  items per second   rises with batch size" ^0
"  cost per item      falls with batch size" ^0
"  service time       rises with batch size" ^0
"  fill time          rises with batch size, and falls with arrival rate" ^0
"  sojourn time       rises with both" ^0
"  a benchmark run at saturation cannot see the fill term at all" ^0
"" ^0

"Amortising a fixed 40 ms over 100 items instead of 10 is correct, and the" ^0
"benchmark that confirmed it was honest: " + str(before_throughput) + " to " + str(after_throughput) + " items per second," ^0
"repeatable. It ran against a saturated queue, where a batch is always full." ^0
"Production arrives at " + str(arrivals_per_second) + " a second, where a batch of 100 takes " + str(int(100 * 1000 / arrivals_per_second)) + " ms to exist," ^0
"and the first request into each one waits " + str(after_first_in) + " ms for a capacity increase" ^0
"it did not need." ^0

fixed_ms_per_batch = 40
ms_per_item = 2
arrivals_per_second = 200
configs = [["no batching", 1], ["before", 10], ["after", 100]]
print("each batch costs " + str(fixed_ms_per_batch) + " ms fixed plus " + str(ms_per_item) + " ms per item")
print("requests arrive at " + str(arrivals_per_second) + " per second")
print("")
print("saturated benchmark - a full batch is always ready")
print("config          batch   ms per batch   items/sec   ms per item   request latency")
for c in configs:
    batch_ms = fixed_ms_per_batch + ms_per_item * c[1]
    throughput = int(c[1] * 1000 / batch_ms)
    per_item_centims = int(batch_ms * 100 / c[1])
    print("  " + c[0] + "    " + str(c[1]) + "        " + str(batch_ms) + "            " + str(throughput) + "         " + str(per_item_centims) + " centims        " + str(batch_ms))
print("")
print("  throughput and cost per item both improve with batch size")
print("  request latency gets worse with batch size, in the same table")
print("")
print("production at " + str(arrivals_per_second) + " arrivals per second")
print("config          batch   fill time   first-in waits   last-in waits   mean wait")
for c in configs:
    batch_ms = fixed_ms_per_batch + ms_per_item * c[1]
    fill_ms = int(c[1] * 1000 / arrivals_per_second)
    first_in = fill_ms + batch_ms
    last_in = batch_ms
    mean_wait = int(fill_ms / 2) + batch_ms
    print("  " + c[0] + "    " + str(c[1]) + "       " + str(fill_ms) + "          " + str(first_in) + "             " + str(last_in) + "            " + str(mean_wait))
print("")
before_batch_ms = fixed_ms_per_batch + ms_per_item * 10
after_batch_ms = fixed_ms_per_batch + ms_per_item * 100
before_throughput = int(10 * 1000 / before_batch_ms)
after_throughput = int(100 * 1000 / after_batch_ms)
before_first_in = int(10 * 1000 / arrivals_per_second) + before_batch_ms
after_first_in = int(100 * 1000 / arrivals_per_second) + after_batch_ms
print("throughput  : " + str(before_throughput) + " -> " + str(after_throughput) + " items/sec, better by " + str(int(after_throughput * 100 / before_throughput)) + " hundredths")
print("worst wait  : " + str(before_first_in) + " -> " + str(after_first_in) + " ms, worse by " + str(int(after_first_in * 100 / before_first_in)) + " hundredths")
print("")
print("at " + str(arrivals_per_second) + " arrivals a second, " + str(before_throughput) + " items/sec was already enough")
print("the capacity that was bought was not short, and the wait that was sold was real")
print("")
print("service time vs sojourn time")
print("  service time  : time inside the batch call            -> " + str(after_batch_ms) + " ms")
print("  fill time     : time waiting for the batch to fill    -> " + str(int(100 * 1000 / arrivals_per_second)) + " ms")
print("  sojourn time  : what the caller experiences           -> " + str(after_first_in) + " ms")
print("  the timer was started when the batch call began")
print("  so it measured " + str(after_batch_ms) + " of the " + str(after_first_in) + " ms the caller waited")
print("  it was not reporting a wrong number, it was reporting a different one")
print("")
print("control - the quantity the change genuinely improved")
configs_measured = 0
for c in configs:
    batch_ms = fixed_ms_per_batch + ms_per_item * c[1]
    throughput = int(c[1] * 1000 / batch_ms)
    configs_measured = configs_measured + 1
    print("  batch " + str(c[1]) + ": " + str(throughput) + " items/sec sustained")
print("  configs measured: " + str(configs_measured) + ", and throughput rises in every step")
print("  the benchmark was right, repeatable, and about the wrong axis")
print("")
fast_arrivals = 10000
print("null control - the same batch of 100 at " + str(fast_arrivals) + " arrivals per second")
fast_fill = int(100 * 1000 / fast_arrivals)
print("  fill time     : " + str(fast_fill) + " ms")
print("  first-in waits: " + str(fast_fill + after_batch_ms) + " ms")
print("  at " + str(arrivals_per_second) + " arrivals it was " + str(after_first_in) + " ms")
print("  same batch size, same code, same overhead constants")
print("  what changed is only how long 100 requests take to exist")
print("")
print("batch size trades one axis against the other, always in the same direction")
print("  items per second   rises with batch size")
print("  cost per item      falls with batch size")
print("  service time       rises with batch size")
print("  fill time          rises with batch size, and falls with arrival rate")
print("  sojourn time       rises with both")
print("  a benchmark run at saturation cannot see the fill term at all")
print("")
print("Amortising a fixed 40 ms over 100 items instead of 10 is correct, and the")
print("benchmark that confirmed it was honest: " + str(before_throughput) + " to " + str(after_throughput) + " items per second,")
print("repeatable. It ran against a saturated queue, where a batch is always full.")
print("Production arrives at " + str(arrivals_per_second) + " a second, where a batch of 100 takes " + str(int(100 * 1000 / arrivals_per_second)) + " ms to exist,")
print("and the first request into each one waits " + str(after_first_in) + " ms for a capacity increase")
print("it did not need.")

each batch costs 40 ms fixed plus 2 ms per item
requests arrive at 200 per second

saturated benchmark - a full batch is always ready
config          batch   ms per batch   items/sec   ms per item   request latency
  no batching    1        42            23         4200 centims        42
  before    10        60            166         600 centims        60
  after    100        240            416         240 centims        240

  throughput and cost per item both improve with batch size
  request latency gets worse with batch size, in the same table

production at 200 arrivals per second
config          batch   fill time   first-in waits   last-in waits   mean wait
  no batching    1       5          47             42            44
  before    10       50          110             60            85
  after    100       500          740             240            490

throughput  : 166 -> 416 items/sec, better by 250 hundredths
worst wait  : 110 -> 740 ms, worse by 672 hundredths

at 200 arrivals a second, 166 items/sec was already enough
the capacity that was bought was not short, and the wait that was sold was real

service time vs sojourn time
  service time  : time inside the batch call            -> 240 ms
  fill time     : time waiting for the batch to fill    -> 500 ms
  sojourn time  : what the caller experiences           -> 740 ms
  the timer was started when the batch call began
  so it measured 240 of the 740 ms the caller waited
  it was not reporting a wrong number, it was reporting a different one

control - the quantity the change genuinely improved
  batch 1: 23 items/sec sustained
  batch 10: 166 items/sec sustained
  batch 100: 416 items/sec sustained
  configs measured: 3, and throughput rises in every step
  the benchmark was right, repeatable, and about the wrong axis

null control - the same batch of 100 at 10000 arrivals per second
  fill time     : 10 ms
  first-in waits: 250 ms
  at 200 arrivals it was 740 ms
  same batch size, same code, same overhead constants
  what changed is only how long 100 requests take to exist

batch size trades one axis against the other, always in the same direction
  items per second   rises with batch size
  cost per item      falls with batch size
  service time       rises with batch size
  fill time          rises with batch size, and falls with arrival rate
  sojourn time       rises with both
  a benchmark run at saturation cannot see the fill term at all

Amortising a fixed 40 ms over 100 items instead of 10 is correct, and the
benchmark that confirmed it was honest: 166 to 416 items per second,
repeatable. It ran against a saturated queue, where a batch is always full.
Production arrives at 200 a second, where a batch of 100 takes 500 ms to exist,
and the first request into each one waits 740 ms for a capacity increase
it did not need.

Trace event types