Project: a log analyser in Nim

loglens reads an access log and prints, for every endpoint, its number of requests, its p95 and largest latency and its count of 5xx errors. Built with -d:release, it read a million lines in 0.43 s of processor time, under an eighth of the 3.65 s that the debug build needed; built with nim js, the same core printed the same reports, byte for byte, on Node.js.

This project builds the tool in modules with a written specification, replaces a first draft of the line rule that accepted +200 and 2_00 and crashed on a twenty-digit latency, works out p95 by nearest rank and compares it with two other definitions, tests it with std/unittest and five black-box cases on both backends, and times the two builds. The practice builds the same report again in Python, step by step.

The specification fixes every line of the report

Here is the sample log of this project: requests to four endpoints, with the two kinds of line that real logs contain and a tool must not count, a method in lower case and a line without its latency:

GET /api/orders 200 35ms
GET /api/orders 200 42ms
POST /api/orders 201 120ms
GET /health 200 1ms
GET /api/orders 500 230ms
GET /api/products 200 18ms
get /api/orders 200 30ms
GET /api/orders 200 38ms
GET /api/products 200 25ms
GET /api/products 503 12ms
GET /health 200 2ms
GET /api/orders 200
POST /api/orders 201 95ms
GET /api/orders 200 40ms

Before any Nim was written, the report was pinned down in seven rules, precise enough that a Python program and a Nim program built from them must print identical bytes:

1. A line is valid when it has four fields separated by single spaces and nothing after them: a method of one or more capital letters A to Z, a path that starts with /, a status of exactly three digits from 100 to 599, which is RFC 9110’s form and range of an HTTP status code, and a latency of one to nine digits followed directly by ms.
2. Every other line, an empty one too, is malformed: counted, and otherwise left out.
3. The endpoint of a valid line is its method, a space and its path, as GET /api/orders.
4. For each endpoint the report prints its count of requests, its p95 and its largest latency, and how many of its statuses are from 500 to 599, the class RFC 9110 calls server errors.
5. The endpoints with the most requests come first; equal counts are ordered by the endpoint’s name, byte by byte.
6. A last line gives the lines read, the endpoints and the malformed lines.
7. A missing argument prints a usage line on standard errorstandard error: The second output stream every program has, meant for error messages. Kept apart from standard output, it lets a report be saved to a file while its errors still reach the terminal or a log. More in “Project: a marks report in Object Pascal” with exit statusexit status: The whole number a program returns to whatever started it: 0 for success by convention, anything else for a failure. Shells and build pipelines read it to decide what happens next. More in “Project: a marks report in Object Pascal” 2, and a file that cannot be read a message with exit status 1.

Step through what loglens does with the lines of sample.log:

The report it printed, five lines from fourteen, is in the session of the next section. GET /api/orders had five valid requests and one 5xx; GET /health and POST /api/orders both had two, so the rule of names put GET first.

Each module has one job, and main only reads the file

loglens is four files of Nim and a test file. parse.nim knows the line rule and nothing else; stats.nim keeps the totals and builds the report; loglens.nim is the program, and the only file that knows about arguments and files. Step through the files and what each one calls:

## loglens/stats: counts, errors and latencies per endpoint, and the report.
import std/[algorithm, tables]
import parse

type
  Endpoint = object
    count, errors: int
    latencies: seq[int]
  Summary* = object
    lines*, malformed*: int
    endpoints: Table[string, Endpoint]

proc nearestRank*(sorted: seq[int]; percent: int): int =
  ## The value at rank ceil(percent / 100 * n) of an ascending seq.
  let rank = (percent * sorted.len + 99) div 100
  sorted[max(rank, 1) - 1]

proc record(e: var Endpoint; req: Request) =
  inc e.count
  if req.status >= 500:
    inc e.errors
  e.latencies.add req.ms

proc add*(s: var Summary; line: string) =
  inc s.lines
  var req: Request
  if parseLine(line, req):
    record(s.endpoints.mgetOrPut(req.endpoint, Endpoint()), req)
  else:
    inc s.malformed

proc report*(s: Summary): seq[string] =
  ## One line per endpoint, the busiest first and equal counts in byte
  ## order of the endpoint; then a line of totals.
  var order: seq[(int, string)]
  for name, e in s.endpoints:
    order.add (-e.count, name)
  order.sort()
  for (negCount, name) in order:
    var lat = s.endpoints[name].latencies
    lat.sort()
    result.add name & " count=" & $(-negCount) & " p95=" &
      $nearestRank(lat, 95) & "ms max=" & $lat[^1] & "ms 5xx=" &
      $s.endpoints[name].errors
  result.add "lines=" & $s.lines & " endpoints=" & $s.endpoints.len &
    " malformed=" & $s.malformed

## loglens: a summary of an access log, one line per endpoint.
import std/os
import loglens/stats

proc main(): int =
  if paramCount() != 1:
    stderr.writeLine "usage: loglens <file>"
    return 2
  var file: File
  if not open(file, paramStr(1)):
    stderr.writeLine "loglens: cannot read ", paramStr(1)
    return 1
  defer: close(file)
  var summary: Summary
  for line in file.lines:            # one line at a time
    summary.add line
  for line in summary.report:
    echo line

quit main()

Three choices in these files carry the lessons of this mini-course. for line in file.lines is a streamstreaming (a file): Reading input one piece at a time, such as one line of a log, and handling each piece before the next is read, so the whole file never has to fit in memory at once.: the file is read one line at a time and never held in memory as a whole, and lines drops each line ending, so a log with Windows line endings reads the same. record takes the endpoint as var Endpoint and gets it straight from the table with mgetOrPut, so the counts change in the table and not in a copy, the trap of objects that the Python lesson showed. And report sorts a seq of pairs, minus the count and the name, because tuples compare field by field: one sort call gives both orders of the specification.

from session import run

# loglens built and run on the sample log, then its unit tests, written with std/unittest.
run("""
cd loglens
nim c --hints:off -o:loglens src/loglens.nim
./loglens cases/sample.log
nim c -r --hints:off tests/test_loglens.nim
""")

$ cd loglens
$ nim c --hints:off -o:loglens src/loglens.nim
$ ./loglens cases/sample.log
GET /api/orders count=5 p95=230ms max=230ms 5xx=1
GET /api/products count=3 p95=25ms max=25ms 5xx=1
GET /health count=2 p95=2ms max=2ms 5xx=0
POST /api/orders count=2 p95=120ms max=120ms 5xx=0
lines=14 endpoints=4 malformed=2
$ nim c -r --hints:off tests/test_loglens.nim

[Suite] parseLine
  [OK] a valid line
  [OK] a sign, an underscore or a fourth digit is not a status
  [OK] spacing and what follows the latency
  [OK] twenty digits are a malformed line, not a crash

[Suite] nearestRank
  [OK] p95 of 20 values is the 19th
  [OK] p95 of 19 values or fewer is the largest

[Suite] report
  [OK] equal counts are in byte order of the endpoint

The report matches the specification line by line, and the seven unit tests of test_loglens.nim passed: three suites, one each for parseLine, nearestRank and report, written with std/unittest, whose check reports the failing expression when a test fails.

A written rule decides what a line is

The first draft of the rule read both numbers with $i, the integer matcher of scanf, and ended with $., which the strscans documentation says to append when nothing may follow the pattern: without it, scanf only checks that the line starts with the pattern. The draft looked strict. Here it is on six lines:

# scanf_i.nim: the first draft of the line rule, with $i for both numbers.
import std/strscans

for line in ["GET /a 200 35ms", "GET /a +200 35ms", "GET /a 0200 35ms",
             "GET /a 2_00 35ms", "GET /a 200 -5ms",
             "GET /a 200 99999999999999999999ms"]:
  var meth, path: string
  var status, ms: int
  try:
    let ok = scanf(line, "$w $+ $i $ims$.", meth, path, status, ms)
    echo line, " -> ", ok, ", status ", status, ", ms ", ms
  except ValueError as e:
    echo line, " -> ValueError: ", e.msg

from session import run

# scanf_i.nim: the first draft of loglens's line rule, which read both numbers with $i, on six lines.
run("""
cd rules
nim c -r --hints:off scanf_i.nim
""")

$ cd rules
$ nim c -r --hints:off scanf_i.nim
GET /a 200 35ms -> true, status 200, ms 35
GET /a +200 35ms -> true, status 200, ms 35
GET /a 0200 35ms -> true, status 200, ms 35
GET /a 2_00 35ms -> true, status 200, ms 35
GET /a 200 -5ms -> true, status 200, ms -5
GET /a 200 99999999999999999999ms -> ValueError: Parsed integer outside of valid range

$i reads with parseutils.parseInt, which has its own idea of an integer: it took +200, 0200 and 2_00 as 200 and a latency of -5, and on twenty digits it raised a ValueError, which in a tool that reads a stranger’s log is a crash on one bad line. None of those is what the specification says. So parse.nim matches the numbers with a matcher of its own, as the strscans documentation shows with its ndigits example: digits(3, 3) for the status and digits(1, 9) for the latency, only ASCII digits, and nine digits at most, which keeps every latency inside the 32 bits of an int on the JavaScript backend:

## loglens/parse: the line rule of the specification.
import std/[strscans, strutils]

type Request* = object
  endpoint*: string   ## the method and the path, as "GET /api/orders"
  status*: int
  ms*: int

proc digits(input: string; value: var int; start: int;
            least, most: int): int =
  ## A scanf matcher: from least to most ASCII digits, no sign, no "_".
  var i = start
  var n = 0
  while i < input.len and input[i] in Digits:
    if i - start == most:
      return 0                       # more digits than allowed
    n = n * 10 + (ord(input[i]) - ord('0'))
    inc i
  if i - start < least:
    return 0
  value = n
  i - start

proc parseLine*(line: string; req: var Request): bool =
  ## True for METHOD PATH STATUS LATENCYms: four fields, single spaces,
  ## nothing after them. Then req holds the request.
  var meth, path: string
  var status, ms: int
  if not scanf(line, "$w $+ ${digits(3, 3)} ${digits(1, 9)}ms$.",
               meth, path, status, ms):
    return false
  if not meth.allCharsInSet({'A'..'Z'}) or not path.startsWith('/'):
    return false
  if status notin 100..599:
    return false
  req = Request(endpoint: meth & " " & path, status: status, ms: ms)
  true

edge.log, one of the black-box cases, holds the five lines that broke the draft, seven more that the rule must refuse and three valid ones. The final rule found 12 of its 15 lines malformed, and none of them stopped the program:

GET /api/orders 200 35ms
GET /api/orders 200 35ms 
GET  /api/orders 200 35ms
GET /api/orders 200 35 ms
GET /api/orders 2_00 35ms
GET /api/orders +200 35ms
GET /api/orders 0200 35ms
GET /api/orders 600 35ms
GET /api/orders 200 -5ms
GET /api/orders 200 99999999999999999999ms
Get /api/orders 200 35ms
GET api/orders 200 35ms

DELETE /api/orders/7 204 0ms
GET /api/orders 599 1000000ms

p95 by nearest rank, and why dashboards disagree

p95 is the latency that 95 % of requests finished within. loglens computes it by the nearest-rank methodnearest-rank percentile: The p-th percentile taken as the value at rank ceil(p / 100 × n) of the n sorted values, counting from 1. It is always one of the values; for p95 and 19 values or fewer it is the largest.: sort the latencies, take the rank 95 % of their count rounded up, (95 * n + 99) div 100 in whole numbers, and report the value at that rank. It is always one of the latencies that happened, never a value between two. The same 20 latencies, by three definitions:

# percentiles.py: one p95 by three definitions, on the same 20 latencies.
import math
import statistics

ms = [12, 15, 18, 20, 22, 25, 25, 28, 30, 33, 35, 38, 40, 42, 45, 50, 60, 80, 120, 230]

ordered = sorted(ms)
rank = math.ceil(0.95 * len(ordered))
print(f"nearest rank, as loglens: {ordered[rank - 1]} (rank {rank} of {len(ordered)})")
print("statistics.quantiles, exclusive:", statistics.quantiles(ms, n=100)[94])
print("statistics.quantiles, inclusive:", statistics.quantiles(ms, n=100, method="inclusive")[94])

nearest rank, as loglens: 120 (rank 19 of 20)
statistics.quantiles, exclusive: 224.5
statistics.quantiles, inclusive: 125.5

R’s documentation describes nine such algorithms, the ones discussed by Hyndman and Fan in their paper on sample quantiles; none is wrong, but a report must say which one it uses. The two of Python interpolate between the two nearest values, so they can report a latency that no request had. Nearest rank has a consequence that surprises people: with 19 values or fewer, the rank works out to the last value, so the p95 of a small endpoint is simply its maximum. That is why every line of sample.log’s report had p95 equal to max, and why the million-line run below does not.

Unit tests check the parts, black-box cases check both programs

The unit tests looked inside: they called parseLine, nearestRank and report directly. A black-box testblack-box test: A test that runs the whole program as a user would, with an input file, and compares only what comes out, standard output, standard error and the exit status, with expected files, without looking at the code inside. More in “Project: a marks report in Object Pascal” runs the program as a user would, a log in and a report out, and compares the report byte for byte with an expected file. loglens has five such cases, and two programs to run them on: the native build, and loglens_node.nim, which imports the same stats.nim and reads the file with Node.js’s fs, because the backend guide lists file management among what the JavaScript target does not have:

## loglens for Node.js: the same core, with the file read by Node's fs.
import std/[os, strutils]
import loglens/stats

proc exists(path: cstring): bool {.importjs: "require('fs').existsSync(#)".}
proc readText(path: cstring): cstring {.importjs: "require('fs').readFileSync(#, 'utf8')".}
proc consoleError(text: cstring) {.importjs: "console.error(#)".}

proc main(): int =
  if paramCount() != 1:
    consoleError("usage: loglens <file>")
    return 2
  if not exists(cstring(paramStr(1))):
    consoleError(cstring("loglens: cannot read " & paramStr(1)))
    return 1
  var pieces = splitLines($readText(cstring(paramStr(1))))
  if pieces.len > 0 and pieces[^1].len == 0:
    pieces.setLen(pieces.len - 1)    # the newline that ends the file
  var summary: Summary
  for line in pieces:
    summary.add line
  for line in summary.report:
    echo line

quit main()

from session import run

# The native build and the Node.js build of loglens, each run on the five cases and compared byte for byte with the
# expected reports; then the two refusals of the specification.
run("""
cd loglens
nim c --hints:off -o:loglens src/loglens.nim
nim js -d:nodejs --hints:off -o:loglens_node.js src/loglens_node.nim
for f in cases/*.log; do ./loglens "$f" | cmp -s - "${f%.log}.out" && echo "native pass $f" || echo "native FAIL $f"; done
for f in cases/*.log; do node loglens_node.js "$f" | cmp -s - "${f%.log}.out" && echo "node pass $f" || echo "node FAIL $f"; done
!./loglens
!./loglens cases/missing.log
""")

$ cd loglens
$ nim c --hints:off -o:loglens src/loglens.nim
$ nim js -d:nodejs --hints:off -o:loglens_node.js src/loglens_node.nim
$ for f in cases/*.log; do ./loglens "$f" | cmp -s - "${f%.log}.out" && echo "native pass $f" || echo "native FAIL $f"; done
native pass cases/crlf.log
native pass cases/edge.log
native pass cases/empty.log
native pass cases/sample.log
native pass cases/ties.log
$ for f in cases/*.log; do node loglens_node.js "$f" | cmp -s - "${f%.log}.out" && echo "node pass $f" || echo "node FAIL $f"; done
node pass cases/crlf.log
node pass cases/edge.log
node pass cases/empty.log
node pass cases/sample.log
node pass cases/ties.log
$ ./loglens
usage: loglens <file>
[exit status 2]
$ ./loglens cases/missing.log
loglens: cannot read cases/missing.log
[exit status 1]

All ten runs passed, so the native build and the JavaScript build agree on every case: the sample, the edges, an empty file, a file of ties and a file with Windows line endings, which file.lines and splitLines both read as the specification means. The last two commands kept the promise of rule 7: no file name gave the usage line and exit status 2, a missing file a message and exit status 1, so a script that runs loglens can tell the two apart.

A million lines: the release build and what it costs

The specification asks loglens to read large logs, and the build mode decides how fast. The session writes a million lines with gen.py, a generator with a fixed seed, so the lines are the same on every run, builds loglens twice and times both builds with /usr/bin/time -p:

"""gen.py: writes n lines in loglens's format to standard output, the same lines on every run (seed 7)."""

import random
import sys

# Endpoints with their share of the traffic and a typical latency in milliseconds.
ENDPOINTS = [
    ("GET /api/orders", 40, 35),
    ("GET /api/products", 30, 20),
    ("POST /api/orders", 15, 110),
    ("GET /health", 10, 2),
    ("DELETE /api/orders", 5, 60),
]


def main():
    n = int(sys.argv[1])
    rnd = random.Random(7)
    names = [e[0] for e in ENDPOINTS]
    weights = [e[1] for e in ENDPOINTS]
    typical = {e[0]: e[2] for e in ENDPOINTS}
    out = []
    for i in range(n):
        name = rnd.choices(names, weights)[0]
        ms = int(typical[name] * rnd.lognormvariate(0, 0.6))
        status = 503 if rnd.random() < 0.01 else 200
        if i % 1000 == 999:
            out.append(f"{name} {status} {ms}")  # a malformed line: no "ms"
        else:
            out.append(f"{name} {status} {ms}ms")
    sys.stdout.write("\n".join(out) + "\n")


main()

from session import run

# A million lines from gen.py, then a debug and a release build of loglens, each timed with /usr/bin/time -p (real is
# the time on the clock, user and sys the processor time), their reports compared, and the size of each program.
run("""
cd speed
python3 gen.py 1000000 > big.log
wc -l < big.log
cd ../loglens
nim c --hints:off -o:loglens_debug src/loglens.nim
nim c --hints:off -d:release -o:loglens_release src/loglens.nim
/usr/bin/time -p ./loglens_debug ../speed/big.log > debug.txt
/usr/bin/time -p ./loglens_release ../speed/big.log > release.txt
cmp debug.txt release.txt
cat release.txt
wc -c < loglens_debug
wc -c < loglens_release
""")

$ cd speed
$ python3 gen.py 1000000 > big.log
$ wc -l < big.log
 1000000
$ cd ../loglens
$ nim c --hints:off -o:loglens_debug src/loglens.nim
$ nim c --hints:off -d:release -o:loglens_release src/loglens.nim
$ /usr/bin/time -p ./loglens_debug ../speed/big.log > debug.txt
real 17.21
user 3.52
sys 0.13
$ /usr/bin/time -p ./loglens_release ../speed/big.log > release.txt
real 5.02
user 0.40
sys 0.03
$ cmp debug.txt release.txt
$ cat release.txt
GET /api/orders count=398963 p95=94ms max=491ms 5xx=3933
GET /api/products count=300174 p95=53ms max=296ms 5xx=3137
POST /api/orders count=149428 p95=295ms max=1387ms 5xx=1506
GET /health count=100391 p95=5ms max=30ms 5xx=946
DELETE /api/orders count=50044 p95=160ms max=749ms 5xx=509
lines=1000000 endpoints=5 malformed=1000
$ wc -c < loglens_debug
  211600
$ wc -c < loglens_release
  116768

cmp printed nothing, so the two reports were identical, down to the byte: the 1,000 malformed lines that gen.py wrote on purpose, one in every thousand, and the five endpoints. With 50,044 requests or more each, p95 now sits well below the largest latency: 94 ms against 491 ms for GET /api/orders. The release build used under an eighth of the debug build’s processor timeprocessor time: The time a processor spent running a program: user, in the program's own code, and sys, in the system's code on its behalf, as /usr/bin/time -p reports them. Unlike real, the time on the clock, it hardly grows when other programs keep the machine busy. More in “Project: a CSV statistics tool in D”, because -d:release turns on the C compiler’s optimiser and turns stack traces off while it keeps every run-time check, as the first lesson of this mini-course showed. The time on the clock was longer than the processor time for both, because the machine was busy with other work, which is why a budget is better stated in processor time.

Practise: loglens again, in Python

Rebuilding loglens in Python from the same seven rules gives the Nim tool a test oracletest oracle: A second, trusted way to work out the expected results of tests, such as a short program written straight from the specification, used to check an implementation on many inputs.: run both on one log, and any line where they differ points at a bug in one of them or a gap in the rules. The lab does it in three steps, the line rule, the p95 and the report, and its sample tests are lines and reports that the Nim tool printed in this lesson’s sessions:

def parse_line(line):
    """(endpoint, status, ms) for a line that loglens counts, or None for a malformed one."""
    # Replace this with your code: it trusts int() and checks nothing else.
    parts = line.split()
    if len(parts) != 4:
        return None
    method, path, status, latency = parts
    try:
        return (method + " " + path, int(status), int(latency.removesuffix("ms")))
    except ValueError:
        return None

from rule import parse_line


def test_lines_of_the_sample():
    """the first line of sample.log, and the one with a 5xx status"""
    assert parse_line("GET /api/orders 200 35ms") == ("GET /api/orders", 200, 35)
    assert parse_line("GET /api/products 503 12ms") == ("GET /api/products", 503, 12)


def test_the_two_malformed_lines_of_the_sample():
    """a method in lower case, and a line without its latency"""
    assert parse_line("get /api/orders 200 30ms") is None
    assert parse_line("GET /api/orders 200") is None


def test_spacing():
    """edge.log: a trailing space, a double space and a space before ms"""
    assert parse_line("GET /api/orders 200 35ms ") is None
    assert parse_line("GET  /api/orders 200 35ms") is None
    assert parse_line("GET /api/orders 200 35 ms") is None


def test_numbers_that_int_would_take():
    """edge.log: an underscore, a sign, four digits and a negative latency"""
    assert parse_line("GET /api/orders 2_00 35ms") is None
    assert parse_line("GET /api/orders +200 35ms") is None
    assert parse_line("GET /api/orders 0200 35ms") is None
    assert parse_line("GET /api/orders 200 -5ms") is None


def test_ranges_and_lengths():
    """edge.log: a status of 600, twenty digits of latency, and the largest valid status"""
    assert parse_line("GET /api/orders 600 35ms") is None
    assert parse_line("GET /api/orders 200 99999999999999999999ms") is None
    assert parse_line("GET /api/orders 599 1000000ms") == ("GET /api/orders", 599, 1000000)


def test_method_and_path():
    """edge.log: a method not in capitals, a path without its slash, and a latency of 0"""
    assert parse_line("Get /api/orders 200 35ms") is None
    assert parse_line("GET api/orders 200 35ms") is None
    assert parse_line("DELETE /api/orders/7 204 0ms") == ("DELETE /api/orders/7", 204, 0)


def test_an_empty_line():
    """the empty line of edge.log"""
    assert parse_line("") is None

import statistics


def p95(values):
    """The 95th percentile of values by the nearest-rank method."""
    # Replace this with your code: it interpolates between two values, which loglens never does.
    if len(values) == 1:
        return values[0]
    return statistics.quantiles(values, n=100)[94]

from p95 import p95


def test_the_twenty_latencies_of_percentiles_py():
    """nearest rank gave 120, the 19th of 20; quantiles gave 224.5 and 125.5"""
    ms = [12, 15, 18, 20, 22, 25, 25, 28, 30, 33, 35, 38, 40, 42, 45, 50, 60, 80, 120, 230]
    assert p95(ms) == 120


def test_five_values_give_the_largest():
    """GET /api/orders in sample.log: p95=230ms, its largest latency"""
    assert p95([35, 42, 230, 38, 40]) == 230


def test_three_values_in_any_order():
    """GET /api/products in sample.log: p95=25ms"""
    assert p95([18, 25, 12]) == 25


def test_one_value():
    """DELETE /api/orders/7 in edge.log: one request of 0 ms"""
    assert p95([0]) == 0


def test_twenty_values_give_the_nineteenth():
    """the unit test of stats.nim: 1 to 20 gives 19"""
    assert p95(list(range(1, 21))) == 19


def test_twenty_one_values():
    """rank (95 * 21 + 99) // 100 = 20, so the 20th of 21"""
    assert p95(list(range(1, 22))) == 20

def parse_line(line):
    """Step 1: (endpoint, status, ms), or None for a malformed line."""
    parts = line.split()
    if len(parts) != 4:
        return None
    method, path, status, latency = parts
    try:
        return (method + " " + path, int(status), int(latency.removesuffix("ms")))
    except ValueError:
        return None


def p95(values):
    """Step 2: the nearest-rank 95th percentile."""
    ordered = sorted(values)
    return ordered[int(0.95 * len(ordered))]


def report(lines):
    """The lines loglens prints for the lines of a log."""
    stats = {}
    malformed = 0
    for line in lines:
        request = parse_line(line)
        if request is None:
            malformed += 1
            continue
        endpoint, status, ms = request
        stats.setdefault(endpoint, []).append((status, ms))
    out = []
    for endpoint in sorted(stats, key=lambda e: -len(stats[e])):
        rows = stats[endpoint]
        latencies = [ms for _, ms in rows]
        errors = sum(1 for status, _ in rows if status >= 500)
        out.append(f"{endpoint} count={len(rows)} p95={p95(latencies)}ms max={max(latencies)}ms 5xx={errors}")
    out.append(f"lines={len(lines)} endpoints={len(stats)} malformed={malformed}")
    return out

from report import report


def test_sample():
    """sample.log: fourteen lines, two of them malformed; GET /health and POST /api/orders tie at 2"""
    lines = [
        'GET /api/orders 200 35ms',
        'GET /api/orders 200 42ms',
        'POST /api/orders 201 120ms',
        'GET /health 200 1ms',
        'GET /api/orders 500 230ms',
        'GET /api/products 200 18ms',
        'get /api/orders 200 30ms',
        'GET /api/orders 200 38ms',
        'GET /api/products 200 25ms',
        'GET /api/products 503 12ms',
        'GET /health 200 2ms',
        'GET /api/orders 200',
        'POST /api/orders 201 95ms',
        'GET /api/orders 200 40ms',
    ]
    assert report(lines) == [
        'GET /api/orders count=5 p95=230ms max=230ms 5xx=1',
        'GET /api/products count=3 p95=25ms max=25ms 5xx=1',
        'GET /health count=2 p95=2ms max=2ms 5xx=0',
        'POST /api/orders count=2 p95=120ms max=120ms 5xx=0',
        'lines=14 endpoints=4 malformed=2',
    ]


def test_ties():
    """ties.log: four endpoints of one request each, in byte order of their names"""
    lines = [
        'POST /b 200 5ms',
        'GET /b 200 5ms',
        'GET /a 200 7ms',
        'POST /a 200 9ms',
    ]
    assert report(lines) == [
        'GET /a count=1 p95=7ms max=7ms 5xx=0',
        'GET /b count=1 p95=5ms max=5ms 5xx=0',
        'POST /a count=1 p95=9ms max=9ms 5xx=0',
        'POST /b count=1 p95=5ms max=5ms 5xx=0',
        'lines=4 endpoints=4 malformed=0',
    ]


def test_edge():
    """edge.log: twelve malformed lines, and a 599 with a latency of 1,000,000 ms"""
    lines = [
        'GET /api/orders 200 35ms',
        'GET /api/orders 200 35ms ',
        'GET  /api/orders 200 35ms',
        'GET /api/orders 200 35 ms',
        'GET /api/orders 2_00 35ms',
        'GET /api/orders +200 35ms',
        'GET /api/orders 0200 35ms',
        'GET /api/orders 600 35ms',
        'GET /api/orders 200 -5ms',
        'GET /api/orders 200 99999999999999999999ms',
        'Get /api/orders 200 35ms',
        'GET api/orders 200 35ms',
        '',
        'DELETE /api/orders/7 204 0ms',
        'GET /api/orders 599 1000000ms',
    ]
    assert report(lines) == [
        'GET /api/orders count=2 p95=1000000ms max=1000000ms 5xx=1',
        'DELETE /api/orders/7 count=1 p95=0ms max=0ms 5xx=0',
        'lines=15 endpoints=2 malformed=12',
    ]


def test_empty():
    """empty.log: no lines at all"""
    lines = []
    assert report(lines) == [
        'lines=0 endpoints=0 malformed=0',
    ]

Then the self-check on the six ideas of the project. Each question comes when its idea is the one you have shown least, and each answer says why it is right or where it goes wrong:

Interview questions

Warm-up, for freshers and mid-level roles: what is the nearest-rank p95, and why does loglens use it?

It is the value at rank ⌈0.95 × n⌉ of the sorted latencies, counted from 1: for 20 latencies the 19th, for 21 the 20th, computed in whole numbers as (95 * n + 99) div 100. loglens uses it because the result is always a latency that really happened, it needs no interpolation, and it is easy to state in a specification and to reproduce in another language, which the Python version of the lab does. Its known effect is that for 19 values or fewer the p95 is the maximum, which is why every endpoint of the sample log showed p95 equal to max. Other tools interpolate: on the lesson’s 20 latencies, Python’s statistics.quantiles gave 224.5 ms by default and 125.5 ms with method="inclusive", where nearest rank gave 120 ms. A report should name its method.

Two longer questions, on a p95 that a dashboard contradicts and on a log too large for the tool’s memory:

Key takeaways

• Seven rules, written before the code, pin down the line rule, the endpoint, the four numbers per endpoint, the order and the exit statuses, which is what lets a Python version print the very same report.
• loglens keeps the rule in parse.nim, the totals in stats.nim and the files in loglens.nim, reads with file.lines one line at a time, and changes the table through mgetOrPut instead of a copy.
• scanf with $i accepted +200, 0200 and 2_00 and raised on twenty digits; matchers of its own make the rule exactly the specification’s.
• p95 by nearest rank is a latency that happened; for 19 values or fewer it is the maximum, and other definitions, such as Python’s two, give other numbers.
• Seven unit tests check the parts, and five black-box cases passed on both the native build and the Node.js build.
• On a million lines the release build needed 0.43 s of processor time against 3.65 s for the debug build, and printed the same report.