The timeout was longer than the caller patience

# Self-authored for the EML case corpus (no external origin). The service
# times out a request after 30 seconds. The client library gives up after 5.
# What the server is doing between those two numbers is computed below.
#
# 30 seconds was chosen carefully and for a reason that is still true. The
# report generator legitimately takes 20 to 25 seconds on a large account, and
# a shorter server timeout would kill those reports halfway through, leaving a
# partial file and a customer with nothing. The number came from measuring the
# slowest legitimate request and adding headroom, which is the correct method.
#
# The client timeout is 5 seconds. It is the library default, it was never
# changed, and there is nothing wrong with it either - 5 seconds is a
# reasonable thing to wait for an API call.
#
# Neither number is wrong on its own. What nobody owns is the relationship
# between them: for 25 seconds the server holds a connection, a worker and a
# database transaction for a request whose caller has already gone.

100 => requests_per_second
8 => slow_percent
30 => server_timeout_s
5 => client_timeout_s
256 => connection_pool

int(requests_per_second * slow_percent / 100) => slow_per_second
server_timeout_s - client_timeout_s => ownerless_seconds

"request rate       : " + str(requests_per_second) + " per second" ^0
"slow requests      : " + str(slow_percent) + " percent = " + str(slow_per_second) + " per second" ^0
"server timeout     : " + str(server_timeout_s) + " seconds" ^0
"client timeout     : " + str(client_timeout_s) + " seconds" ^0
"connection pool    : " + str(connection_pool) ^0
"" ^0

# ---- the window nobody owns ----

slow_per_second * ownerless_seconds => ownerless_in_flight

"each slow request keeps working for " + str(ownerless_seconds) + " seconds after its caller gave up" ^0
"" ^0
"  slow requests entering per second        : " + str(slow_per_second) ^0
"  seconds each spends unowned              : " + str(ownerless_seconds) ^0
"  unowned requests in flight at any moment : " + str(ownerless_in_flight) ^0
"" ^0

"  connections held by unowned work : " + str(ownerless_in_flight) + " of " + str(connection_pool) ^0
"  that is " + str(int(ownerless_in_flight * 100 / connection_pool)) + " percent of the pool" ^0
"" ^0

# ---- what the pool has left ----

connection_pool - ownerless_in_flight => pool_available

"  connections available to callers still waiting : " + str(pool_available) ^0
"  requests per second those can serve at " + str(client_timeout_s) + "s each : " + str(int(pool_available / client_timeout_s)) ^0
"  offered load                                   : " + str(requests_per_second) ^0
"" ^0

# ---- the loop this closes ----
#
# A caller that times out retries. The retry needs a connection. The pool is
# full of work for callers who already left. So the retry waits, times out,
# and retries again, and each attempt adds another 25 unowned seconds.

"what a client does at " + str(client_timeout_s) + " seconds" ^0
"  it gives up and retries" ^0
"  the original request keeps running for another " + str(ownerless_seconds) + " seconds" ^0
"  the retry is a NEW request that also needs a connection" ^0
"" ^0
"attempt   unowned seconds added   cumulative unowned per slow request" ^0
0 => cumulative
for a in [1:4]:
    cumulative + ownerless_seconds => cumulative
    "  " + str(a) + "         " + str(ownerless_seconds) + "                      " + str(cumulative) ^0
"" ^0
"  three attempts by one caller occupy " + str(cumulative) + " connection-seconds" ^0
"  and the caller has been gone for " + str(cumulative - ownerless_seconds) + " of them" ^0
"" ^0

# ---- which number to change ----
#
# Raising the client timeout to the server's would keep the caller present for
# the whole 30 seconds, which is what the 30 was designed for. Lowering the
# server timeout to the client's would kill the legitimate 25-second reports.
# The third option costs nothing on either axis.

"three options" ^0
"  raise the client timeout to " + str(server_timeout_s) + "s" ^0
"    unowned seconds per slow request : 0" ^0
"    cost : a caller may wait " + str(server_timeout_s) + "s, which the " + str(server_timeout_s) + "s was chosen for" ^0
"  lower the server timeout to " + str(client_timeout_s) + "s" ^0
"    unowned seconds per slow request : 0" ^0
"    cost : every legitimate 25-second report is killed" ^0
"  cancel server work when the connection closes" ^0
"    unowned seconds per slow request : 0" ^0
"    cost : none on either axis; the server stops when nobody is listening" ^0
"" ^0

# ---- the control ----
#
# Both timeouts are individually correct and both were chosen by measurement.
# Reviewing either one alone finds nothing, because neither one is wrong.

"control - is either number wrong on its own" ^0
"  slowest legitimate request     : 25 seconds" ^0
"  server timeout                 : " + str(server_timeout_s) + " seconds, which is above it" ^0
"  is the server timeout too long : no, it is measured plus headroom" ^0
"  is the client timeout too short: no, 5 seconds is a reasonable API wait" ^0
"  both reviews pass, and the defect is in neither number" ^0
"" ^0
"  it is in the difference, and a difference has no owner" ^0
"" ^0

# ---- the null control ----
#
# The same two numbers with no slow requests. Everything finishes inside the
# client timeout, the gap is never entered, and the configuration is exactly
# right. The pair only misbehaves on the requests that reach into the gap.

0 => nc_slow_per_second

"null control - the same timeouts when nothing is slow" ^0
"  slow requests per second      : " + str(nc_slow_per_second) ^0
"  unowned requests in flight    : " + str(nc_slow_per_second * ownerless_seconds) ^0
"  pool used by unowned work     : 0 of " + str(connection_pool) ^0
"  same 30 and same 5, and the gap costs nothing" ^0
"  the gap is only entered by requests that outlive the client timeout," ^0
"  which is " + str(slow_percent) + " percent of them here and 0 percent in a healthy hour" ^0
"" ^0

# ---- the rule ----

"a timeout pair, read as a pair" ^0
"  client shorter than server   the server works for nobody in the gap" ^0
"  client longer than server    the caller waits for an answer already killed" ^0
"  equal                        neither, and no headroom for the network" ^0
"  the only stable arrangement is one where the server notices the caller left" ^0
"  every review that reads one number at a time approves all three" ^0
"" ^0

"The " + str(server_timeout_s) + " seconds came from measuring the slowest legitimate request and adding" ^0
"headroom, and the " + str(client_timeout_s) + " is a sensible default nobody should have to justify. Between" ^0
"them sits a " + str(ownerless_seconds) + "-second window in which the server holds a connection, a worker" ^0
"and a transaction for a caller who has gone: " + str(ownerless_in_flight) + " of the " + str(connection_pool) + " pool, " + str(int(ownerless_in_flight * 100 / connection_pool)) + " percent," ^0
"spent on work whose result nobody will read." ^0

requests_per_second = 100
slow_percent = 8
server_timeout_s = 30
client_timeout_s = 5
connection_pool = 256
slow_per_second = int(requests_per_second * slow_percent / 100)
ownerless_seconds = server_timeout_s - client_timeout_s
print("request rate       : " + str(requests_per_second) + " per second")
print("slow requests      : " + str(slow_percent) + " percent = " + str(slow_per_second) + " per second")
print("server timeout     : " + str(server_timeout_s) + " seconds")
print("client timeout     : " + str(client_timeout_s) + " seconds")
print("connection pool    : " + str(connection_pool))
print("")
ownerless_in_flight = slow_per_second * ownerless_seconds
print("each slow request keeps working for " + str(ownerless_seconds) + " seconds after its caller gave up")
print("")
print("  slow requests entering per second        : " + str(slow_per_second))
print("  seconds each spends unowned              : " + str(ownerless_seconds))
print("  unowned requests in flight at any moment : " + str(ownerless_in_flight))
print("")
print("  connections held by unowned work : " + str(ownerless_in_flight) + " of " + str(connection_pool))
print("  that is " + str(int(ownerless_in_flight * 100 / connection_pool)) + " percent of the pool")
print("")
pool_available = connection_pool - ownerless_in_flight
print("  connections available to callers still waiting : " + str(pool_available))
print("  requests per second those can serve at " + str(client_timeout_s) + "s each : " + str(int(pool_available / client_timeout_s)))
print("  offered load                                   : " + str(requests_per_second))
print("")
print("what a client does at " + str(client_timeout_s) + " seconds")
print("  it gives up and retries")
print("  the original request keeps running for another " + str(ownerless_seconds) + " seconds")
print("  the retry is a NEW request that also needs a connection")
print("")
print("attempt   unowned seconds added   cumulative unowned per slow request")
cumulative = 0
for a in range(1, 5):
    cumulative = cumulative + ownerless_seconds
    print("  " + str(a) + "         " + str(ownerless_seconds) + "                      " + str(cumulative))
print("")
print("  three attempts by one caller occupy " + str(cumulative) + " connection-seconds")
print("  and the caller has been gone for " + str(cumulative - ownerless_seconds) + " of them")
print("")
print("three options")
print("  raise the client timeout to " + str(server_timeout_s) + "s")
print("    unowned seconds per slow request : 0")
print("    cost : a caller may wait " + str(server_timeout_s) + "s, which the " + str(server_timeout_s) + "s was chosen for")
print("  lower the server timeout to " + str(client_timeout_s) + "s")
print("    unowned seconds per slow request : 0")
print("    cost : every legitimate 25-second report is killed")
print("  cancel server work when the connection closes")
print("    unowned seconds per slow request : 0")
print("    cost : none on either axis; the server stops when nobody is listening")
print("")
print("control - is either number wrong on its own")
print("  slowest legitimate request     : 25 seconds")
print("  server timeout                 : " + str(server_timeout_s) + " seconds, which is above it")
print("  is the server timeout too long : no, it is measured plus headroom")
print("  is the client timeout too short: no, 5 seconds is a reasonable API wait")
print("  both reviews pass, and the defect is in neither number")
print("")
print("  it is in the difference, and a difference has no owner")
print("")
nc_slow_per_second = 0
print("null control - the same timeouts when nothing is slow")
print("  slow requests per second      : " + str(nc_slow_per_second))
print("  unowned requests in flight    : " + str(nc_slow_per_second * ownerless_seconds))
print("  pool used by unowned work     : 0 of " + str(connection_pool))
print("  same 30 and same 5, and the gap costs nothing")
print("  the gap is only entered by requests that outlive the client timeout,")
print("  which is " + str(slow_percent) + " percent of them here and 0 percent in a healthy hour")
print("")
print("a timeout pair, read as a pair")
print("  client shorter than server   the server works for nobody in the gap")
print("  client longer than server    the caller waits for an answer already killed")
print("  equal                        neither, and no headroom for the network")
print("  the only stable arrangement is one where the server notices the caller left")
print("  every review that reads one number at a time approves all three")
print("")
print("The " + str(server_timeout_s) + " seconds came from measuring the slowest legitimate request and adding")
print("headroom, and the " + str(client_timeout_s) + " is a sensible default nobody should have to justify. Between")
print("them sits a " + str(ownerless_seconds) + "-second window in which the server holds a connection, a worker")
print("and a transaction for a caller who has gone: " + str(ownerless_in_flight) + " of the " + str(connection_pool) + " pool, " + str(int(ownerless_in_flight * 100 / connection_pool)) + " percent,")
print("spent on work whose result nobody will read.")

request rate       : 100 per second
slow requests      : 8 percent = 8 per second
server timeout     : 30 seconds
client timeout     : 5 seconds
connection pool    : 256

each slow request keeps working for 25 seconds after its caller gave up

  slow requests entering per second        : 8
  seconds each spends unowned              : 25
  unowned requests in flight at any moment : 200

  connections held by unowned work : 200 of 256
  that is 78 percent of the pool

  connections available to callers still waiting : 56
  requests per second those can serve at 5s each : 11
  offered load                                   : 100

what a client does at 5 seconds
  it gives up and retries
  the original request keeps running for another 25 seconds
  the retry is a NEW request that also needs a connection

attempt   unowned seconds added   cumulative unowned per slow request
  1         25                      25
  2         25                      50
  3         25                      75
  4         25                      100

  three attempts by one caller occupy 100 connection-seconds
  and the caller has been gone for 75 of them

three options
  raise the client timeout to 30s
    unowned seconds per slow request : 0
    cost : a caller may wait 30s, which the 30s was chosen for
  lower the server timeout to 5s
    unowned seconds per slow request : 0
    cost : every legitimate 25-second report is killed
  cancel server work when the connection closes
    unowned seconds per slow request : 0
    cost : none on either axis; the server stops when nobody is listening

control - is either number wrong on its own
  slowest legitimate request     : 25 seconds
  server timeout                 : 30 seconds, which is above it
  is the server timeout too long : no, it is measured plus headroom
  is the client timeout too short: no, 5 seconds is a reasonable API wait
  both reviews pass, and the defect is in neither number

  it is in the difference, and a difference has no owner

null control - the same timeouts when nothing is slow
  slow requests per second      : 0
  unowned requests in flight    : 0
  pool used by unowned work     : 0 of 256
  same 30 and same 5, and the gap costs nothing
  the gap is only entered by requests that outlive the client timeout,
  which is 8 percent of them here and 0 percent in a healthy hour

a timeout pair, read as a pair
  client shorter than server   the server works for nobody in the gap
  client longer than server    the caller waits for an answer already killed
  equal                        neither, and no headroom for the network
  the only stable arrangement is one where the server notices the caller left
  every review that reads one number at a time approves all three

The 30 seconds came from measuring the slowest legitimate request and adding
headroom, and the 5 is a sensible default nobody should have to justify. Between
them sits a 25-second window in which the server holds a connection, a worker
and a transaction for a caller who has gone: 200 of the 256 pool, 78 percent,
spent on work whose result nobody will read.

Trace event types