Trace in Short-Lived Workloads

The whole calculation of the previous lesson rested on one assumption: if a log field was written, it is in hand at the time of the response. In a persistent service this is true. In short-lived workloads it is not. When a task container lives for forty seconds and is terminated, only the items it produced that were written out can be queried; the rest goes away with the process. The difference between collecting evidence in a cloud environment and in persistent systems was measured in the Cloud and Virtualization Security course; it is not repeated here, it becomes an input.

This lesson measures only the application trace: which application items have been written out by the time the workload dies. The measure is called the collectable item window, and it cannot be reduced to a single number, because the lost items are not randomly distributed within the stream — they are all at the end.

• DR17. The workload set is fictional: 2,000 runs, four life bands. The lives come from a generator whose seed is visible.
• DR18. Items are produced at a constant rate within the workload and written to a local buffer. The shipper writes out at most batch items every interval seconds.
• DR19. When the workload terminates, everything left in the buffer is lost. A final flush can be made only if the grace period covers the flush duration; in the model the flush takes 1.2 seconds and the default grace period is 0.5 seconds.
• DR20. A question depends on the item produced at a relative position in the workload’s life. If the item was not written out, that question is unanswered for that workload; the unit of measure is again the unanswered question.
• DR21. The durations and rates are data; they are not a measurement made on this page.

The Collectable Item Window

// trace.mjs — the window of items that can be written out in short-lived workloads is measured.
// IT IS A MODEL: the workloads, the lives and the item rates are fictional.
export const SEED = 20260502, WORKLOAD_COUNT = 2000;
export const RATE = 6, INTERVAL = 5, BATCH = 200, FLUSH_TIME = 1.2, GRACE = 0.5;
const rng = (t) => { let s = t >>> 0;
  return () => (s = (s * 1664525 + 1013904223) >>> 0) / 4294967296; };
const r = rng(SEED);

// Class = the life band of the workload. The failed exit lives shortest and loses most.
export const CLASSES = [
  { name: "short task", share: 0.55, lo: 3, hi: 20 },
  { name: "batch job", share: 0.25, lo: 20, hi: 120 },
  { name: "request handler", share: 0.15, lo: 60, hi: 400 },
  { name: "failed exit", share: 0.05, lo: 1, hi: 4 },
];
const pickClass = (u) => { let t = 0;
  for (const s of CLASSES) { t += s.share; if (u < t) return s; } return CLASSES.at(-1); };
export const WORKLOADS = Array.from({ length: WORKLOAD_COUNT }, () => {
  const s = pickClass(r());
  return { cls: s.name, life: s.lo + r() * (s.hi - s.lo) };
});

// The buffer is FIFO: each flush carries at most BATCH items. Whatever is left in the buffer
// when the workload dies is gone; the final flush happens only if the grace period covers the flush duration.
export function run(life, rate = RATE, interval = INTERVAL, grace = GRACE) {
  const items = Math.max(1, Math.floor(life * rate));
  let sent = 0, requests = 0;
  const flush = (t) => {
    const produced = Math.min(items, Math.floor(t * rate) + 1);
    const g = Math.min(BATCH, produced - sent);
    if (g > 0) { sent += g; requests++; }
  };
  for (let t = interval; t <= life; t += interval) flush(t);
  if (grace >= FLUSH_TIME) flush(life);
  return { items, sent, lost: items - sent, requests };
}

// Question = [text, relative position of the item in the workload's life]. If the item was not
// written out, the question is unanswered for that workload.
export const QUESTIONS = [
  ["which account sent the request", 0.00],
  ["which endpoint was called", 0.10],
  ["which dependency was called", 0.45],
  ["what was the authorization decision", 0.85],
  ["which error ended the workload", 1.00],
];

export function aggregate(rate = RATE, interval = INTERVAL, grace = GRACE) {
  let items = 0, sent = 0, requests = 0;
  const answerCounts = QUESTIONS.map(() => 0);
  for (const w of WORKLOADS) {
    const o = run(w.life, rate, interval, grace);
    items += o.items; sent += o.sent; requests += o.requests;
    QUESTIONS.forEach(([, p], j) => {
      if (Math.floor(p * (o.items - 1)) < o.sent) answerCounts[j]++;
    });
  }
  return { items, sent, lost: items - sent, requests, answerCounts };
}

export const gen = (B) => (h) => h.map((v, j) => (j ? String(v).padStart(B[j])
  : String(v).padEnd(B[0]))).join("");

if (import.meta.url === `file://${process.argv[1]}`) {
  console.log(`model (seed ${SEED}): ${WORKLOAD_COUNT} workloads, ${RATE} items/s, flush ` +
    `interval ${INTERVAL} s, batch ${BATCH} items, grace period ${GRACE} s, ` +
    `flush duration ${FLUSH_TIME} s`);
  const y = gen([18, 8, 11, 12, 12, 11, 9]);
  console.log("\n" + y(["workload class", "count", "mean life", "produced", "written out",
    "lost", "ratio"]));
  for (const s of CLASSES) {
    const l = WORKLOADS.filter((w) => w.cls === s.name).map((w) => run(w.life));
    const pr = l.reduce((t, o) => t + o.items, 0), g = l.reduce((t, o) => t + o.sent, 0);
    const lf = WORKLOADS.filter((w) => w.cls === s.name).reduce((t, w) => t + w.life, 0);
    console.log(y([s.name, l.length, (lf / l.length).toFixed(1), pr, g, pr - g,
      (g / pr).toFixed(2)]));
  }
  const t = aggregate();
  console.log(`\ntotal ${t.items} items produced, ${t.sent} written out, ` +
    `${t.lost} lost (${((t.lost / t.items) * 100).toFixed(1)}%)`);
  const z = gen([38, 10, 14, 8]);
  console.log("\n" + z(["question", "position", "answered", "ratio"]));
  QUESTIONS.forEach(([m, p], j) => console.log(z([m, p.toFixed(2),
    `${t.answerCounts[j]}/${WORKLOAD_COUNT}`, (t.answerCounts[j] / WORKLOAD_COUNT).toFixed(2)])));
}

model (seed 20260502): 2000 workloads, 6 items/s, flush interval 5 s, batch 200 items, grace period 0.5 s, flush duration 1.2 s

workload class       count  mean life    produced written out       lost    ratio
short task            1091       11.5       74404       57738      16666     0.78
batch job              536       71.2      228687      221405       7282     0.97
request handler        281      217.8      367056      363361       3695     0.99
failed exit             92        2.5        1354           0       1354     0.00

total 671501 items produced, 642504 written out, 28997 lost (4.3%)

question                                position      answered   ratio
which account sent the request              0.00     1757/2000    0.88
which endpoint was called                   0.10     1757/2000    0.88
which dependency was called                 0.45     1757/2000    0.88
what was the authorization decision         0.85     1218/2000    0.61
which error ended the workload              1.00      115/2000    0.06

The two tables are two different readings of the same run, and they look nothing alike. In the top table the total loss is 4.3%. On a dashboard this number reads as “log collection is healthy”; and indeed, of the 671,501 items produced, 642,504 were written out. There is no fault anywhere in the log pipeline; the shipper is running, the network is up, the destination is writable.

The bottom table reads the same data per question and says something else. The items produced in the first half of the workload’s life can be collected in 1,757 of the 2,000 workloads. The item where the authorization decision is written, in 1,218 of them, and the last item, which says how the workload ended, in only 115. That is, the question “which error ended the workload” is unanswered in 94% of the workloads — even though the log was written. The lost-item rate and the answerability rate are not the same thing, because the lost items are not randomly distributed within the stream; they are all at the end, and the items most wanted in a response are also the ones at the end.

The class table writes down where the loss concentrates. The request handler class lives 218 seconds on average and writes out 99% of its items. The failed exit class lives 2.5 seconds on average and not a single one of its items comes out: 92 workloads, 1,354 items, zero. The flush interval is five seconds; a workload that lives two and a half seconds never reaches the first periodic flush, and since the grace period does not cover the flush duration, the final flush cannot be made. This class is only two in a thousand of the total items, but it is the class most looked at in a response: a workload ending unexpectedly and quickly is already the starting reason for the investigation.

The reason the total loss rate misleads is in this table too. The total is an average weighted by the item count, and most items are produced by long-lived workloads: the 281 request handlers alone write 367,056 items, while the 1,091 short tasks write 74,404. The long-lived class’s 99% rate pulls the total up, while the short-lived class’s 78% and the failed exit’s zero are lost in the total. A collection rate that is not measured per workload reports the rate of the class that produces the most items as the rate of the whole environment. When the same data is read per workload, it turns out that 92 workloads are completely silent, and that number is written nowhere in the total rate.

Level of Detail and Collection Settings

// settings.mjs — two setting axes are run: the level of detail (items/s) and the flush layout
// (interval, grace period). What is measured is not the item count but the answered question. IT IS A MODEL.
import { RATE, INTERVAL, GRACE, WORKLOAD_COUNT, QUESTIONS, aggregate, gen } from "./trace.mjs";

const y = gen([10, 11, 12, 8, 14, 12, 17]);
console.log(y(["detail", "produced", "written out", "lost", "authz (0.85)", "last (1.00)",
  "answered pairs"]));
for (const mult of [1, 2, 4, 8]) {
  const t = aggregate(RATE * mult);
  const pairs = t.answerCounts.reduce((a, b) => a + b, 0);
  console.log(y([`${mult}x`, t.items, t.sent, ((t.lost / t.items) * 100).toFixed(1) + "%",
    (t.answerCounts[3] / WORKLOAD_COUNT).toFixed(2), (t.answerCounts[4] / WORKLOAD_COUNT).toFixed(2),
    `${pairs}/${QUESTIONS.length * WORKLOAD_COUNT}`]));
}

const z = gen([9, 10, 12, 14, 12, 12, 16]);
console.log("\n" + z(["interval", "grace", "written out", "authz (0.85)", "last (1.00)",
  "requests", "extra core-sec"]));
for (const grace of [GRACE, 1.5]) for (const interval of [5, 2, 1]) {
  const t = aggregate(RATE, interval, grace);
  console.log(z([interval, grace, t.sent, (t.answerCounts[3] / WORKLOAD_COUNT).toFixed(2),
    (t.answerCounts[4] / WORKLOAD_COUNT).toFixed(2), t.requests,
    (WORKLOAD_COUNT * (grace - GRACE)).toFixed(0)]));
}

const base = aggregate(), dense = aggregate(RATE * 8), wide = aggregate(RATE, 1, 1.5);
console.log(`\nwhen detail is raised 8 times, items written out rise from ${base.sent} to ` +
  `${dense.sent} but the authorization decision question falls from ` +
  `${base.answerCounts[3]} workloads to ${dense.answerCounts[3]} workloads`);
console.log(`the widest setting (interval 1 s, grace period 1.5 s) writes out the last item in ` +
  `${wide.answerCounts[4]} workloads instead of ${base.answerCounts[4]} at the same detail; ` +
  `its cost is ${wide.requests - base.requests} extra flush requests and ` +
  `${(WORKLOAD_COUNT * (1.5 - GRACE) / 60).toFixed(0)} core-minutes of extra lifetime`);

detail       produced written out    lost  authz (0.85) last (1.00)   answered pairs
1x             671501      642504    4.3%          0.61        0.06       6604/10000
2x            1344000     1283327    4.5%          0.59        0.03       6500/10000
4x            2688990     2564937    4.6%          0.58        0.01       6454/10000
8x            5378988     4272000   20.6%          0.00        0.00       5221/10000

interval      grace written out  authz (0.85) last (1.00)    requests  extra core-sec
5               0.5      642504          0.61        0.06       21360               0
2               0.5      662111          0.89        0.15       55024               0
1               0.5      668090          1.00        0.31      111065               0
5               1.5      671501          1.00        1.00       23245            2000
2               1.5      671501          1.00        1.00       56715            2000
1               1.5      671501          1.00        1.00      112444            2000

when detail is raised 8 times, items written out rise from 642504 to 4272000 but the authorization decision question falls from 1218 workloads to 0 workloads
the widest setting (interval 1 s, grace period 1.5 s) writes out the last item in 2000 workloads instead of 115 at the same detail; its cost is 91084 extra flush requests and 33 core-minutes of extra lifetime

The first table gives the fact this course shows for the second time. When the level of detail is raised eight times, the items written out rise from 642,504 to 4,272,000 — six and a half times more records. The same move lowers the number of workloads answering the authorization decision question from 1,218 to zero. The mechanism appears not in the last column but in the lost column: at eight times the detail the production rate rises to 48 items per second, while the shipper carries at most 200 items in five seconds, that is, 40 per second. When production exceeds carrying capacity, the buffer starts to accumulate, and the end of the stream never gets its turn. Writing more records, with the carrying capacity fixed, pushes the last-written item further back in the queue; the total items rise, the answered questions fall.

The three rows above this break are the soft form of the same fact. When the detail is raised two and four times, the capacity is not yet exceeded; even so, the answered question–workload pairs fall from 6,604 to 6,454. There is no gain, because the added items fall inside the already collectable window; what is lost is again the item at the end.

The second table writes what the two settings buy. Lowering the flush interval from five seconds to one raises the authorization decision question from 0.61 to 1.00, but the last item is still collected in only 31% of the workloads — because the problem is not the interval, it is that the flush at the moment of closing cannot be made at all. When the grace period is extended enough to cover the flush duration, all questions are answered in every workload even with the five-second interval. What determines the collectable item window is not how often the flush happens, but that the workload can complete a flush before it dies.

The cost is written in two columns. Lowering the interval to one raises the flush requests from 21,360 to 111,065: more than five times the network requests, fifty-five requests per workload. Extending the grace period by one second brings 2,000 core-seconds, that is, 33 core-minutes of extra lifetime, and delays the termination of every workload. Together they cost 91,084 extra requests. A third cost is not visible in the table but it is in the ledger of the earlier lessons: every item written out falls inside the fixed retention budget of the previous lesson and shortens the retention days.

Summary

• In short-lived workloads the measure is not the items written but the items that can be written out; whatever is left in the buffer when the workload dies is lost.
• The loss rate and the answerability rate are separate numbers: in the model, while the loss is 4.3%, the last item of the workload can be collected in only 115 of 2,000 workloads.
• The loss is not equally distributed across classes: not a single item comes out of the 92 workloads of the failed exit class, which lives 2.5 seconds on average, yet the starting reason for an investigation is most often this class.
• Raising the level of detail can lower the answer: at eight times the detail the items written out grow six and a half times while the number of workloads answering the authorization decision question falls from 1,218 to zero, because the production rate exceeds the carrying capacity and the end of the stream never gets its turn.
• What determines the window is not the flush frequency but the workload being able to complete a flush before it dies: when the grace period is extended, even the five-second interval is enough.
• The cost is measured: 91,084 extra flush requests, 33 core-minutes of extra lifetime, and the share every item written out takes from the fixed retention budget.

Next Step

Up to this point all the logs, alerts and items have come from within the organization itself. A vulnerability in an application is often heard of from somewhere else: someone looking from the outside finds it and reports it. This flow is not a detection pipeline, it is a work queue; its input is reports written by people, its output is items that are fixed or rejected, and its measure is not the item count but time. The next lesson measures the external report intake and the bug bounty program on this axis: how many days pass from report to verification and from verification to fix, how many of the incoming reports are duplicates, and at what point opening the channel clogs the queue.