Log Collection

Every answer in the previous lesson was a number: how many milliseconds, how many requests, how many errors. But no number answers the question of why — it is known that billing’s p95 is 1042 milliseconds, it is not known which lock it was waiting on. That information does not live in a metric, it lives in the text the process writes itself.

A log line is a different kind of thing from a metric: not a predefined series, but text written at the moment of the event, with unbounded cardinality. That is where its cost comes from. A metric pipeline carries a few thousand numbers a second; a log pipeline carries tens of thousands of lines a second. This lesson splits that pipeline into three layers — the log agent, the buffer, and the indexer — and counts how many records are lost at each layer.

The stream is the regional measurement network’s own stream and is fictional; no real log store is run, what gets counted is a model run second by second with node.

ML19. Line rates, the mix, and the layer limits are fictional and written in advance; there is no randomness in the simulation, the same input gives the same number on every run. ML20. The log agent reads 1400 lines a second and holds a local buffer of 30,000 lines; the queue holds 300,000 lines, and the indexer processes 1000 lines a second. ML21. Truncation happens at 512 bytes. An error line is 620 bytes, and its last 108 bytes hold the error code and the transaction ID the process generated. ML22. When the buffer fills, the type of the dropped lines matches that second’s composition; the queue makes no distinction by type. ML23. If a line is indexed more than 60 seconds after it was written, it is counted as “late-visible” and is treated as absent for a question asked at event time. ML24. A question is answered if the loss on the line type it requires is under the accepted margin: 10% for rate questions, 1% for count questions. Q11 is never answered at any load because its metered value is not written to the log, and Q12 is never answered because there is no shared identity across the chain of services.

Three Layers and Their Limits

// stream.mjs — the log stream is run through the agent, buffer, and indexing layers; loss is counted at every layer.
export const BASE = 232, MIX = { request: 0.86, error: 0.02, "job-step": 0.12 };
export const BYTES = { request: 180, error: 620, "job-step": 240 };
export const JOB_START = 600, JOB_END = 1200, JOB_EXTRA = 900;   // nightly batch window, all job-step
export const LIMITS = { agentRead: 1400, agentBuffer: 30000, queue: 300000, indexer: 1000,
  truncate: 512, visibility: 60 };
export const WINDOW = 3600;

export const run = (load, s = LIMITS) => {
  let buffer = 0, queue = 0;
  const d = { produced: 0, agentDropped: 0, queueDropped: 0, indexed: 0, lateVisible: 0,
    maxDelay: 0, type: {}, droppedType: {} };
  for (const t of Object.keys(BYTES)) { d.type[t] = 0; d.droppedType[t] = 0; }
  for (let sec = 0; sec < WINDOW; sec++) {
    const input = {};                                    // this second's line composition
    for (const t of Object.keys(BYTES)) input[t] = load * BASE * MIX[t];
    if (sec >= JOB_START && sec < JOB_END) input["job-step"] += load * JOB_EXTRA;
    const total = Object.values(input).reduce((a, b) => a + b, 0);
    for (const t of Object.keys(BYTES)) d.type[t] += input[t];
    d.produced += total;

    buffer += total;                                     // layer 1: agent
    const read = Math.min(buffer, s.agentRead);
    buffer -= read;
    if (buffer > s.agentBuffer) {
      const dropped = buffer - s.agentBuffer;            // dropped lines carry this second's composition
      for (const t of Object.keys(BYTES)) d.droppedType[t] += dropped * input[t] / total;
      d.agentDropped += dropped; buffer = s.agentBuffer;
    }
    queue += read;                                        // layer 2: buffer queue
    if (queue > s.queue) {                                // queue makes no type distinction, loss spreads over all types
      const dropped = queue - s.queue;
      for (const t of Object.keys(BYTES)) d.droppedType[t] += dropped * input[t] / total;
      d.queueDropped += dropped; queue = s.queue;
    }
    const written = Math.min(queue, s.indexer);           // layer 3: indexer
    queue -= written; d.indexed += written;
    const delay = buffer / s.agentRead + queue / s.indexer;
    d.maxDelay = Math.max(d.maxDelay, delay);
    if (delay > s.visibility) d.lateVisible += written;
  }
  return d;
};

The three layers break in three distinct ways, and that distinction is what matters for this lesson. The agent and the queue drop lines — the record ceases to exist. The indexer does not drop lines, it delays them — the record arrives eventually, but it is not there at the moment the question is asked. Truncation neither drops nor delays; it leaves the line where it is and cuts off its tail.

Layer-by-Layer Loss at Two Loads

// layers.mjs — layer-by-layer loss at two loads, and the question the loss leaves unanswered.
import { BASE, MIX, BYTES, JOB_START, JOB_END, JOB_EXTRA, LIMITS, WINDOW, run } from "./stream.mjs";

const fmt = (x) => Math.round(x).toLocaleString("en-US");
console.log(`log stream (fictional, second by second): ${WINDOW} s, base ${BASE} lines/s` +
  ` (${Object.entries(MIX).map(([t, p]) => `${t} ${p * 100}%`).join(", ")})`);
console.log(`nightly batch job ${JOB_START}-${JOB_END} s window, +${JOB_EXTRA} lines/s, all job-step`);
console.log(`limits: agent read ${LIMITS.agentRead}/s buffer ${fmt(LIMITS.agentBuffer)};` +
  ` queue ${fmt(LIMITS.queue)}; indexer ${LIMITS.indexer}/s; truncate ${LIMITS.truncate} bytes;` +
  ` visibility threshold ${LIMITS.visibility} s\n`);

console.log("load   produced   agent dropped  queue dropped  truncated  max delay  late-visible  loss %");
const results = {};
for (const load of [1, 2]) {
  const d = run(load);
  const truncated = Object.entries(d.type).reduce((t, [type, n]) => t + (BYTES[type] > LIMITS.truncate ? n : 0), 0);
  results[load] = { ...d, truncated };
  console.log(`${`${load}x`.padEnd(6)}${fmt(d.produced).padStart(9)}${fmt(d.agentDropped).padStart(14)}` +
    `${fmt(d.queueDropped).padStart(14)}${fmt(truncated).padStart(10)}` +
    `${`${d.maxDelay.toFixed(0)} s`.padStart(15)}${fmt(d.lateVisible).padStart(13)}` +
    `${`${(100 * d.agentDropped / d.produced).toFixed(1)}%`.padStart(9)}`);
}

console.log("\nthe type of loss and the question it leaves unanswered");
console.log("loss                      affected lines                                    question left unanswered");
const double = results[2], ROWS = [
  ["agent buffer filled (2x)", `job-step ${fmt(double.droppedType["job-step"])} lines` +
    ` (${(100 * double.droppedType["job-step"] / double.type["job-step"]).toFixed(1)}%)`, "Q5 Q6"],
  ["truncation (both loads)", `last ${BYTES.error - LIMITS.truncate} bytes of error lines (100%)`, "Q10 Q12"],
  ["indexing delay (2x)", `${fmt(double.lateVisible)} lines became visible more than ${LIMITS.visibility} s late`,
    "every question asked at event time"]];
for (const [a, b, c] of ROWS) console.log(`${a.padEnd(26)}${b.padEnd(50)}${c}`);

// against the question set: [id, line type, does the field truncate in the queue, accepted loss share]
const QUESTIONS_LOG = [["Q1", "request", false, 0.10], ["Q2", "request", false, 0.10],
  ["Q3", "request", false, 0.10], ["Q4", "request", false, 0.10], ["Q5", "job-step", false, 0.01],
  ["Q6", "job-step", false, 0.01], ["Q7", "request", false, 0.10], ["Q8", "request", false, 0.10],
  ["Q9", "job-step", false, 0.01], ["Q10", "error", true, 0.10]];
const mb = (b) => (b / 1024 ** 2).toFixed(0);
console.log("\nagainst the question set (Q11's value is never written to the log, Q12 has no identity across the chain)");
console.log("load    stored MB  lost MB  request loss  job-step loss   answered  MB/question  unanswered");
for (const load of [1, 2]) {
  const d = results[load], lossRate = (k) => d.droppedType[k] / d.type[k];
  const produced = Object.keys(BYTES).reduce((t, k) => t + d.type[k] * BYTES[k], 0);
  const stored = Object.keys(BYTES).reduce((t, k) =>
    t + (d.type[k] - d.droppedType[k]) * Math.min(BYTES[k], LIMITS.truncate), 0);
  const answered = QUESTIONS_LOG.filter(([, type, inQueue, tolerance]) =>
    lossRate(type) <= tolerance && !(inQueue && BYTES[type] > LIMITS.truncate));
  console.log(`${`${load}x`.padEnd(6)}${mb(stored).padStart(11)}${mb(produced - stored).padStart(9)}` +
    `${`${(100 * lossRate("request")).toFixed(1)}%`.padStart(14)}${`${(100 * lossRate("job-step")).toFixed(1)}%`.padStart(15)}` +
    `${`${answered.length}/12`.padStart(11)}${mb(stored / answered.length).padStart(13)}  ` +
    [...QUESTIONS_LOG.filter((s) => !answered.includes(s)).map(([k]) => k), "Q11", "Q12"].join(" "));
}

log stream (fictional, second by second): 3600 s, base 232 lines/s (request 86%, error 2%, job-step 12%)
nightly batch job 600-1200 s window, +900 lines/s, all job-step
limits: agent read 1400/s buffer 30,000; queue 300,000; indexer 1000/s; truncate 512 bytes; visibility threshold 60 s

load   produced   agent dropped  queue dropped  truncated  max delay  late-visible  loss %
1x    1,375,200             0             0    16,704           79 s      170,000     0.0%
2x    2,750,400       488,400             0    33,408          261 s      895,000    17.8%

the type of loss and the question it leaves unanswered
loss                      affected lines                                    question left unanswered
agent buffer filled (2x)  job-step 400,315 lines (31.3%)                    Q5 Q6
truncation (both loads)   last 108 bytes of error lines (100%)              Q10 Q12
indexing delay (2x)       895,000 lines became visible more than 60 s late  every question asked at event time

against the question set (Q11's value is never written to the log, Q12 has no identity across the chain)
load    stored MB  lost MB  request loss  job-step loss   answered  MB/question  unanswered
1x            278        2          0.0%           0.0%       9/12           31  Q10 Q11 Q12
2x            449      111          6.0%          31.3%       6/12           75  Q5 Q6 Q9 Q10 Q11 Q12

At single-fold load, not a single line drops. The agent can read 1400 lines a second, and the peak rate is 1132; the queue does not even come close to its capacity of three hundred thousand lines. But the pipeline still does not run cleanly: the indexer processes 1000 lines a second, and during the batch job window the input rises above that. The buildup stays in the queue, there is no loss — only a delay. The maximum delay is 79 seconds, and 170,000 lines are indexed above the sixty-second visibility threshold. Those lines have not been lost; they are not there at the moment they are asked for.

The Silence of Truncation

Truncation does the same thing at both loads, and it is the smallest-looking number in the table: two megabytes at single-fold load. But the share of lines it affects is one hundred percent. An error line is 620 bytes, the truncation limit is 512; the last 108 bytes of every error line are cut off, and two fields sit there — the error code and the transaction ID the process generated.

The shape of the loss also matters. A dropped line makes itself known: counters do not add up, the line sequence skips. A truncated line gives nothing away. The store holds 16,704 error lines, all of them readable, all of them with their timestamp and service name intact. Only the error code field is empty, and it is empty not because the error code was never written, but because the line was cut off. The two cases cannot be told apart on the query side; both return the same empty cell.

The cost is Q10: the question of which error code rose cannot be answered from the log. In the previous lesson the same question was answered from a metric — the result label was five-valued, and the error rate could be computed. But the result label on the metric splits into five classes; the error code in the log carries hundreds of distinct values, and that is what actually narrows the investigation.

When the Load Doubles

The second row answers the question: the agent breaks first. The peak rate rises to 2264 lines a second, the agent’s read rate is 1400, and the 864 lines a second in between build up in the buffer; the thirty-thousand-line buffer fills in thirty-five seconds, and for the remaining five hundred sixty-five seconds the excess drops — 488,400 lines, 17.8% of what was produced.

The queue never breaks, because the agent is already not passing the excess through. This is the characteristic behavior of a layered pipeline: the narrowest layer protects the others, and because it protects them, the others’ limits are never tested. Increasing queue capacity does not gain this pipeline a single line.

The distribution of the dropped lines is not a coincidence either. The moment the buffer overflows is the batch job window, and in that window eighty-two percent of the input is job-step lines; of the 488,400 dropped lines, 400,315 are job-step — 31.3% of all job-step lines. How many readings the nightly job processed and why it finished late can no longer be asked from the log.

But the loss does not stop there. There is no rule choosing which line drops when the buffer overflows; six percent of request lines drop too. Request lines that have nothing to do with the batch job go missing only because they pass through the same buffer. One layer overflowing corrupts questions that had nothing to do with causing the overflow — for count questions, six percent is already more than enough; for rate questions, the result is not wrong, but it is skewed, and the skew is invisible.

The last table writes this course’s rule in its clearest form. When the load doubles, the stored data rises from 278 megabytes to 449 megabytes — a sixty-one percent increase. Questions answered drop from 9 to 6. Cost per question rises from 31 megabytes to 75, two and a half times. More data was collected, fewer questions were answered; the two are faces of the same event.

Which Limit Change Brings Which Question Back

Now that the layer that breaks is known, the question is this: how many questions does widening a single limit bring back?

// mitigation.mjs — single limit changes at 2x load: which question comes back, at how many megabytes.
import { BYTES, LIMITS, run } from "./stream.mjs";

const QUESTIONS_LOG = [["Q1", "request", false, 0.10], ["Q2", "request", false, 0.10],
  ["Q3", "request", false, 0.10], ["Q4", "request", false, 0.10], ["Q5", "job-step", false, 0.01],
  ["Q6", "job-step", false, 0.01], ["Q7", "request", false, 0.10], ["Q8", "request", false, 0.10],
  ["Q9", "job-step", false, 0.01], ["Q10", "error", true, 0.10]];
const mb = (b) => (b / 1024 ** 2).toFixed(0), fmt = (x) => Math.round(x).toLocaleString("en-US");
const CHANGES = [["no change", {}],
  ["buffer 30k -> 300k", { agentBuffer: 300000 }],
  ["agent read 1400 -> 2400", { agentRead: 2400 }],
  ["indexer 1000 -> 2400", { indexer: 2400 }],
  ["truncate 512 -> 1024 bytes", { truncate: 1024 }],
  ["agent 2400 + indexer 2400", { agentRead: 2400, indexer: 2400 }]];

console.log("single limit changes at 2x load");
console.log("change                           agent dropped  queue dropped    delay    stored MB    answered  MB/question");
for (const [name, changes] of CHANGES) {
  const limits = { ...LIMITS, ...changes }, d = run(2, limits), lossRate = (k) => d.droppedType[k] / d.type[k];
  const stored = Object.keys(BYTES).reduce((t, k) =>
    t + (d.type[k] - d.droppedType[k]) * Math.min(BYTES[k], limits.truncate), 0);
  const answered = QUESTIONS_LOG.filter(([, type, inQueue, tolerance]) =>
    lossRate(type) <= tolerance && !(inQueue && BYTES[type] > limits.truncate));
  console.log(`${name.padEnd(31)}${fmt(d.agentDropped).padStart(15)}${fmt(d.queueDropped).padStart(15)}` +
    `${`${d.maxDelay.toFixed(0)} s`.padStart(9)}${mb(stored).padStart(13)}` +
    `${`${answered.length}/12`.padStart(12)}${mb(stored / answered.length).padStart(13)}`);
}

single limit changes at 2x load
change                           agent dropped  queue dropped    delay    stored MB    answered  MB/question
no change                              488,400              0    261 s          449        6/12           75
buffer 30k -> 300k                     218,400         69,000    454 s          495        6/12           83
agent read 1400 -> 2400                      0        459,400    299 s          455        6/12           76
indexer 1000 -> 2400                   488,400              0     21 s          449        6/12           75
truncate 512 -> 1024 bytes             488,400              0    261 s          452        7/12           65
agent 2400 + indexer 2400                    0              0      0 s          556        9/12           62

Three of the four single steps bring back no question. Multiplying the buffer by ten cuts the agent’s loss in half, but it moves the loss to the queue and raises the delay from 261 seconds to 454: the buffer does not prevent loss, it delays it, and a delay is a loss too. Raising the agent’s read rate zeroes out the agent’s loss, but in exchange 459,400 lines drop in the queue — the total loss is nearly the same, only the layer has changed. Speeding up the indexer alone saves not a single line; it only cuts the delay from 261 seconds to 21, which is a real gain, but on a different line item.

The one cheap step that brings a question back is the truncation limit: raising it from 512 to 1024 bytes costs three extra megabytes and brings back Q10 — cost per question drops from 75 megabytes to 65. The only way to bring the other questions back is to change two limits together: loss zeroes out, delay drops to zero, questions answered rises to 9/12, and cost per question falls to 62 megabytes — the lowest of the six rows. The pipeline’s bottleneck is not in a single layer, it is in the ratio between two layers.

Summary

• The three layers break in three distinct ways: the agent and queue drop lines, the indexer delays them, truncation leaves the line and cuts off its tail.
• At single-fold load no line drops, but the indexing delay rises to 79 seconds and 170,000 lines become visible past the 60-second visibility threshold — data left unanswered without being lost.
• Truncation is independent of load and erases the last 108 bytes on one hundred percent of error lines; an empty field and a truncated field cannot be told apart in a query, and Q10 stays unanswered.
• When the load doubles, the agent breaks first: 488,400 lines drop (17.8%), the queue never overflows — the narrowest layer never lets the others’ limits be tested.
• The overflow is not selective: 400,315 of the dropped lines are job-step (31.3%), but 6% of request lines drop too; questions unrelated to the batch job get corrupted as well.
• As stored data rises from 278 to 449 MB, questions answered drop from 9/12 to 6/12; cost per question rises from 31 MB to 75 MB. Four of the single limit increases bring back no question; the buffer moves the loss to the queue, agent speed just moves the loss to a different layer, and the solution is in the ratio between two limits.

Next Step

Up to this point the log line was counted as a whole: how many lines produced, how many lines dropped, how many bytes stored. But the line that reaches the store is still text, and very few questions can be answered on text alone — you can search for a string, you can count how many lines it appears in; you cannot ask which service’s error rate rose in which environment. The next lesson parses real log lines and turns them into searchable fields: how many questions unstructured text answers, how many questions become answerable once fields are produced, and what the line the parsing rule silently misses costs.