The cheaper path was taken often enough to cost more

# Self-authored for the EML case corpus (no external origin). A request handler
# calls five things. The code review flagged the slowest of them. Which one that
# is depends on a sort order, and both orders are computed below.
#
# Reviewing by cost per call is the right instinct and is what a reviewer can
# actually do. Per-call cost is a property of the function: it can be read off
# the code, reasoned about at the diff, and measured by a microbenchmark that
# runs in a second. Call count is a property of the caller, and of the caller's
# caller, and of the data - none of which is in the diff. So the reviewer sorted
# by the number the review could see, which is the honest thing to do with the
# information available.
#
# Total cost is per-call cost times call count. Neither factor dominates in
# general, and a per-call sort is a total-cost sort only when the counts happen
# to be similar. Here they span four orders of magnitude.
#
# The function with the lowest per-call cost in the table has the highest total
# cost in the table, and the two orderings are close to exact reverses.

# [function, microseconds per call, calls per request]
[["audit_log", 5000, 2], ["render_template", 800, 12], ["db_query", 300, 40], ["checksum", 5, 20000], ["debug_log", 20, 50000]] => calls

"function            us per call   calls   total us" ^0
0 => grand_total
for c in calls:
    c[1] * c[2] => total
    grand_total + total => grand_total
    "  " + c[0] + "        " + str(c[1]) + "         " + str(c[2]) + "     " + str(total) ^0
"" ^0
"  request total: " + str(grand_total) + " us = " + str(int(grand_total / 1000)) + " ms" ^0
"" ^0

# ---- the two orderings ----

"sorted by cost per call, which is what the review saw" ^0
"  1  audit_log         5000 us per call" ^0
"  2  render_template    800" ^0
"  3  db_query           300" ^0
"  4  debug_log           20" ^0
"  5  checksum             5" ^0
"" ^0
"sorted by total cost, which is what the request pays" ^0
"  1  debug_log        " + str(20 * 50000) + " us total" ^0
"  2  checksum         " + str(5 * 20000) ^0
"  3  db_query         " + str(300 * 40) ^0
"  4  audit_log        " + str(5000 * 2) ^0
"  5  render_template  " + str(800 * 12) ^0
"" ^0
"  audit_log is first by per-call and fourth by total" ^0
"  debug_log is fourth by per-call and first by total" ^0
"" ^0

# ---- share of the request ----

"function            share of request time" ^0
for c in calls:
    c[1] * c[2] => total
    "  " + c[0] + "        " + str(int(total * 1000 / grand_total)) + " per mille" ^0
"" ^0

# ---- what removing each one saves ----
#
# The review's recommendation was to make audit_log asynchronous, which is real
# work and does remove its cost. It removes the amount computed here.

"if the flagged function were removed entirely" ^0
5000 * 2 => audit_total
20 * 50000 => debug_total
"  audit_log removed : saves " + str(audit_total) + " us, " + str(int(audit_total * 1000 / grand_total)) + " per mille of the request" ^0
"  debug_log removed : saves " + str(debug_total) + " us, " + str(int(debug_total * 1000 / grand_total)) + " per mille of the request" ^0
"  the review recommended the first" ^0
"" ^0

# ---- the ratio between the two factors ----

"per-call ratio  : audit_log is " + str(int(5000 / 20)) + " times debug_log" ^0
"call count ratio: debug_log is " + str(int(50000 / 2)) + " times audit_log" ^0
"total ratio     : debug_log is " + str(int(debug_total / audit_total)) + " times audit_log" ^0
"" ^0
"  the per-call sort is correct about a 250x difference" ^0
"  it is silent about a 25000x difference in the other factor" ^0
"  and the second factor is 100 times larger than the first" ^0
"" ^0

# ---- the control ----
#
# Per-call cost is not a wrong measurement. Every per-call number in the table
# is exactly right, and a microbenchmark would reproduce each one. The product
# is the thing nobody computed, and the product needs a number that is not in
# the function.

"control - are the per-call numbers themselves wrong" ^0
0 => rows
0 => rows_consistent
for c in calls:
    c[1] * c[2] => total
    rows + 1 => rows
    if int(total / c[2]) == c[1]:
        rows_consistent + 1 => rows_consistent
"  rows checked                 : " + str(rows) ^0
"  per-call cost reproduces total: " + str(rows_consistent) + " of " + str(rows) ^0
"  every per-call figure is correct and the review used them correctly" ^0
"  what is missing is a column, not a correction" ^0
"" ^0

# ---- the null control ----
#
# The same five functions, called the same number of times as each other. Now
# the per-call sort and the total sort agree exactly, and reviewing by per-call
# cost finds the right target. The defect is not "per-call cost is the wrong
# metric" - it is "per-call cost ranks correctly only when counts are level".

10 => level_calls
"null control - the same functions, all called " + str(level_calls) + " times" ^0
"function            total us   rank by total" ^0
"  audit_log        " + str(5000 * level_calls) + "      1" ^0
"  render_template  " + str(800 * level_calls) + "       2" ^0
"  db_query         " + str(300 * level_calls) + "       3" ^0
"  debug_log        " + str(20 * level_calls) + "        4" ^0
"  checksum         " + str(5 * level_calls) + "         5" ^0
"  this is the per-call order, unchanged" ^0
"  same functions, same per-call costs, and now the review's sort is right" ^0
"" ^0

# ---- the rule ----

"what a diff shows and what it does not" ^0
"  cost of the line added        visible" ^0
"  how often the line runs       not visible" ^0
"  where the loop around it is   not visible, it may be three frames up" ^0
"  what the data volume is       not visible, it is a production fact" ^0
"  a reviewer sorting by what a diff shows will sort by per-call cost" ^0
"" ^0

"Per-call cost is what a reviewer can read off a diff and confirm with a" ^0
"one-second microbenchmark, and every per-call figure here is correct. Total" ^0
"cost needs the call count, which lives in the caller and in the data. Sorted" ^0
"by per-call, debug_log is fourth of five. It is " + str(int(debug_total * 1000 / grand_total)) + " per mille of the request," ^0
"and the function the review flagged is " + str(int(audit_total * 1000 / grand_total)) + " per mille." ^0

calls = [["audit_log", 5000, 2], ["render_template", 800, 12], ["db_query", 300, 40], ["checksum", 5, 20000], ["debug_log", 20, 50000]]
print("function            us per call   calls   total us")
grand_total = 0
for c in calls:
    total = c[1] * c[2]
    grand_total = grand_total + total
    print("  " + c[0] + "        " + str(c[1]) + "         " + str(c[2]) + "     " + str(total))
print("")
print("  request total: " + str(grand_total) + " us = " + str(int(grand_total / 1000)) + " ms")
print("")
print("sorted by cost per call, which is what the review saw")
print("  1  audit_log         5000 us per call")
print("  2  render_template    800")
print("  3  db_query           300")
print("  4  debug_log           20")
print("  5  checksum             5")
print("")
print("sorted by total cost, which is what the request pays")
print("  1  debug_log        " + str(20 * 50000) + " us total")
print("  2  checksum         " + str(5 * 20000))
print("  3  db_query         " + str(300 * 40))
print("  4  audit_log        " + str(5000 * 2))
print("  5  render_template  " + str(800 * 12))
print("")
print("  audit_log is first by per-call and fourth by total")
print("  debug_log is fourth by per-call and first by total")
print("")
print("function            share of request time")
for c in calls:
    total = c[1] * c[2]
    print("  " + c[0] + "        " + str(int(total * 1000 / grand_total)) + " per mille")
print("")
print("if the flagged function were removed entirely")
audit_total = 5000 * 2
debug_total = 20 * 50000
print("  audit_log removed : saves " + str(audit_total) + " us, " + str(int(audit_total * 1000 / grand_total)) + " per mille of the request")
print("  debug_log removed : saves " + str(debug_total) + " us, " + str(int(debug_total * 1000 / grand_total)) + " per mille of the request")
print("  the review recommended the first")
print("")
print("per-call ratio  : audit_log is " + str(int(5000 / 20)) + " times debug_log")
print("call count ratio: debug_log is " + str(int(50000 / 2)) + " times audit_log")
print("total ratio     : debug_log is " + str(int(debug_total / audit_total)) + " times audit_log")
print("")
print("  the per-call sort is correct about a 250x difference")
print("  it is silent about a 25000x difference in the other factor")
print("  and the second factor is 100 times larger than the first")
print("")
print("control - are the per-call numbers themselves wrong")
rows = 0
rows_consistent = 0
for c in calls:
    total = c[1] * c[2]
    rows = rows + 1
    if int(total / c[2]) == c[1]:
        rows_consistent = rows_consistent + 1
print("  rows checked                 : " + str(rows))
print("  per-call cost reproduces total: " + str(rows_consistent) + " of " + str(rows))
print("  every per-call figure is correct and the review used them correctly")
print("  what is missing is a column, not a correction")
print("")
level_calls = 10
print("null control - the same functions, all called " + str(level_calls) + " times")
print("function            total us   rank by total")
print("  audit_log        " + str(5000 * level_calls) + "      1")
print("  render_template  " + str(800 * level_calls) + "       2")
print("  db_query         " + str(300 * level_calls) + "       3")
print("  debug_log        " + str(20 * level_calls) + "        4")
print("  checksum         " + str(5 * level_calls) + "         5")
print("  this is the per-call order, unchanged")
print("  same functions, same per-call costs, and now the review's sort is right")
print("")
print("what a diff shows and what it does not")
print("  cost of the line added        visible")
print("  how often the line runs       not visible")
print("  where the loop around it is   not visible, it may be three frames up")
print("  what the data volume is       not visible, it is a production fact")
print("  a reviewer sorting by what a diff shows will sort by per-call cost")
print("")
print("Per-call cost is what a reviewer can read off a diff and confirm with a")
print("one-second microbenchmark, and every per-call figure here is correct. Total")
print("cost needs the call count, which lives in the caller and in the data. Sorted")
print("by per-call, debug_log is fourth of five. It is " + str(int(debug_total * 1000 / grand_total)) + " per mille of the request,")
print("and the function the review flagged is " + str(int(audit_total * 1000 / grand_total)) + " per mille.")

function            us per call   calls   total us
  audit_log        5000         2     10000
  render_template        800         12     9600
  db_query        300         40     12000
  checksum        5         20000     100000
  debug_log        20         50000     1000000

  request total: 1131600 us = 1131 ms

sorted by cost per call, which is what the review saw
  1  audit_log         5000 us per call
  2  render_template    800
  3  db_query           300
  4  debug_log           20
  5  checksum             5

sorted by total cost, which is what the request pays
  1  debug_log        1000000 us total
  2  checksum         100000
  3  db_query         12000
  4  audit_log        10000
  5  render_template  9600

  audit_log is first by per-call and fourth by total
  debug_log is fourth by per-call and first by total

function            share of request time
  audit_log        8 per mille
  render_template        8 per mille
  db_query        10 per mille
  checksum        88 per mille
  debug_log        883 per mille

if the flagged function were removed entirely
  audit_log removed : saves 10000 us, 8 per mille of the request
  debug_log removed : saves 1000000 us, 883 per mille of the request
  the review recommended the first

per-call ratio  : audit_log is 250 times debug_log
call count ratio: debug_log is 25000 times audit_log
total ratio     : debug_log is 100 times audit_log

  the per-call sort is correct about a 250x difference
  it is silent about a 25000x difference in the other factor
  and the second factor is 100 times larger than the first

control - are the per-call numbers themselves wrong
  rows checked                 : 5
  per-call cost reproduces total: 5 of 5
  every per-call figure is correct and the review used them correctly
  what is missing is a column, not a correction

null control - the same functions, all called 10 times
function            total us   rank by total
  audit_log        50000      1
  render_template  8000       2
  db_query         3000       3
  debug_log        200        4
  checksum         50         5
  this is the per-call order, unchanged
  same functions, same per-call costs, and now the review's sort is right

what a diff shows and what it does not
  cost of the line added        visible
  how often the line runs       not visible
  where the loop around it is   not visible, it may be three frames up
  what the data volume is       not visible, it is a production fact
  a reviewer sorting by what a diff shows will sort by per-call cost

Per-call cost is what a reviewer can read off a diff and confirm with a
one-second microbenchmark, and every per-call figure here is correct. Total
cost needs the call count, which lives in the caller and in the data. Sorted
by per-call, debug_log is fourth of five. It is 883 per mille of the request,
and the function the review flagged is 8 per mille.

Trace event types