From e488650e95732ae8a25451a64eb7d63ab19f94ac Mon Sep 17 00:00:00 2001 From: tamnd <1218621+tamnd@users.noreply.github.com> Date: Sun, 6 Sep 2026 19:33:23 +0700 Subject: [PATCH] Fix a claim in the ring buffer blueprint: the trace file does say how many Merged yesterday and wrong in one place. The blueprint said the trace file does not say that events were lost. It does. Its header carries entries-in-buffer/entries-written, and the second of those two numbers is this processor's kept events plus its overrun, added up when the header is printed. On the capture in section 5 it would read 273/44275. What is actually true is narrower and more useful. Neither way of reading a trace gives you both halves. The trace file says how many, once, at the top, in a header a reader skips on the way to the lines, and marks nothing in the body, so the body reads the same whether nothing was lost or almost everything was. trace_pipe is the other way round: it prints CPU:0 [LOST 44002 EVENTS] at the position the loss happened and has no header at all. The header is also a display option rather than part of the format, so turning context-info off removes the one admission the file makes. The project's own parser had this right the whole time. TraceLog in kxray/models/flat.py reads that banner and its docstring says a trace where the two numbers differ has holes in it that nothing in the body admits to. The blueprint should have agreed with it. Section 3 gains a step 22 for where the header number comes from, section 6 and section 9 are corrected, and the diagram gains the header line and a band that says each way of reading a trace tells you half. Three new citations, R76 to R78, all confirmed against the pinned tree. Invariant 11 is unchanged and still holds: the iterator's missed events flag is never set on an ordinary buffer. --- .../trace-ring-buffer-overrun.diagram.py | 52 ++++-- .../trace-ring-buffer-overrun.excalidraw | 171 +++++++++++++++--- .../assets/trace-ring-buffer-overrun.svg | 17 +- blueprints/trace-ring-buffer.md | 20 +- blueprints/trace-ring-buffer.refs.toml | 30 +++ 5 files changed, 226 insertions(+), 64 deletions(-) diff --git a/blueprints/assets/trace-ring-buffer-overrun.diagram.py b/blueprints/assets/trace-ring-buffer-overrun.diagram.py index cbf59cd..b0d3514 100644 --- a/blueprints/assets/trace-ring-buffer-overrun.diagram.py +++ b/blueprints/assets/trace-ring-buffer-overrun.diagram.py @@ -14,14 +14,14 @@ ALT = ( "A picture in four parts, about how a full trace buffer loses events without saying so. " - "Across the top, a ring of four boxes labelled sub buffer 0 to sub buffer 3, joined " - "left to right by arrows with a dashed arrow wrapping from the last one back to the first. " - "The first box is also labelled head, the oldest, the third is labelled tail, writing here " - "now, and a separate box sits outside the ring labelled reader page, off the ring, with a " - "note that the writer will never touch it. Underneath on the left, a column headed what one " - "writer does, with three boxes reading down: read the tail page, read the two timestamps, and " - "add my length to the write index with one atomic add. That last box forks. The left branch " - "is labelled it fits and holds one box reading write the data and commit. The right branch is " + "Across the top, a ring of four boxes labelled sub buffer 0 to sub buffer 3, joined left to " + "right by arrows with a dashed arrow wrapping from the last one back to the first. The first " + "box is also labelled head, the oldest, the third is labelled tail, writing here now, and a " + "separate box sits outside the ring labelled reader page, off the ring, with a note that the " + "writer will never touch it. Underneath on the left, a column headed what one writer does, " + "with three boxes reading down: read the tail page, read the two timestamps, and add my " + "length to the write index with one atomic add. That last box forks. The left branch is " + "labelled it fits and holds one box reading write the data and commit. The right branch is " "labelled it does not fit and holds three boxes in a red style reading the next page is the " "head, throw that whole page away and add its events to overrun, and move the tail onto it. A " "note beside the red branch says nothing waits, nothing fails, and no caller is told. On the " @@ -32,14 +32,16 @@ "consuming read, take overrun minus last overrun, and print CPU:0 LOST 44002 EVENTS. The " "right column, the trace file, has boxes reading iterator read, ask for the iterator's missed " "events flag, and a red box reading the writer never sets that bit on an ordinary buffer, so " - "the flag is zero and nothing prints. Across the bottom is a red band reading a quiet trace " - "file is not evidence that nothing was lost, and under it a line saying the stats file under " - "per_cpu is the only place that tells you." + "nothing marks the body. An arrow leads from that red box to a wide box holding the header " + "line of the trace file, entries-in-buffer slash entries-written 273 slash 44275. Across the " + "bottom is a red band reading each way of reading a trace tells you half of what was lost, " + "and under it a line saying trace_pipe says where and prints no header, while the trace file " + "says how many, once, in a header a reader skips, and marks nothing in the body." ) def scene() -> Scene: - s = Scene("How a full ring buffer loses events", width=1240, height=1112) + s = Scene("How a full ring buffer loses events", width=1240, height=1180) s.note(40, 44, "How a full ring buffer loses events", font_size=20) s.note( @@ -172,7 +174,7 @@ def scene() -> Scene: 882, 210, 60, - "the writer never sets that bit,\nso the flag is zero", + "the writer never sets that bit,\nso nothing marks the body", style="warn", font_size=12, ) @@ -182,23 +184,35 @@ def scene() -> Scene: s.arrow(t1, t2) s.arrow(t2, t3) + header = s.box( + 760, + 954, + 440, + 56, + "the header of the trace file: entries-in-buffer/entries-written 273/44275", + style="accent", + font_size=12, + mono=True, + ) + s.arrow(t3, header, sides=("bottom", "top")) + # -- the part that costs a debugging session -------------------------------------------------- band = s.box( 40, - 988, + 1056, 1160, 56, - "a quiet trace file is not evidence that nothing was lost", + "each way of reading a trace tells you half of what was lost", style="warn", font_size=17, ) - s.arrow(t3, band) + s.arrow(header, band) s.note( 40, - 1068, - "The stats file under per_cpu is the only place that tells you, and the counter to read is " - "named after the setting.", + 1136, + "trace_pipe says where and prints no header. The trace file says how many, once, in a " + "header a reader skips, and marks nothing in the body.", font_size=13, muted=True, ) diff --git a/blueprints/assets/trace-ring-buffer-overrun.excalidraw b/blueprints/assets/trace-ring-buffer-overrun.excalidraw index d856a87..1e3105f 100644 --- a/blueprints/assets/trace-ring-buffer-overrun.excalidraw +++ b/blueprints/assets/trace-ring-buffer-overrun.excalidraw @@ -2356,8 +2356,8 @@ "link": null, "locked": false, "type": "text", - "text": "the writer never sets that bit,\nso the flag is zero", - "originalText": "the writer never sets that bit,\nso the flag is zero", + "text": "the writer never sets that bit,\nso nothing marks the body", + "originalText": "the writer never sets that bit,\nso nothing marks the body", "fontSize": 12, "fontFamily": 1, "textAlign": "center", @@ -2540,13 +2540,13 @@ }, { "id": "box046", - "x": 40, - "y": 988, - "width": 1160, + "x": 760, + "y": 954, + "width": 440, "height": 56, "angle": 0, - "strokeColor": "#e03131", - "backgroundColor": "#ffe3e3", + "strokeColor": "#1971c2", + "backgroundColor": "#d0ebff", "fillStyle": "solid", "strokeWidth": 2, "strokeStyle": "solid", @@ -2574,12 +2574,12 @@ }, { "id": "box046-text", - "x": 358.2, - "y": 1005.375, - "width": 523.6, - "height": 21.25, + "x": 739.1, + "y": 974.5, + "width": 481.8, + "height": 15.0, "angle": 0, - "strokeColor": "#e03131", + "strokeColor": "#1971c2", "backgroundColor": "transparent", "fillStyle": "solid", "strokeWidth": 2, @@ -2598,10 +2598,10 @@ "link": null, "locked": false, "type": "text", - "text": "a quiet trace file is not evidence that nothing was lost", - "originalText": "a quiet trace file is not evidence that nothing was lost", - "fontSize": 17, - "fontFamily": 1, + "text": "the header of the trace file: entries-in-buffer/entries-written 273/44275", + "originalText": "the header of the trace file: entries-in-buffer/entries-written 273/44275", + "fontSize": 12, + "fontFamily": 3, "textAlign": "center", "verticalAlign": "middle", "containerId": "box046", @@ -2610,10 +2610,10 @@ }, { "id": "arrow047", - "x": 990, - "y": 912.0, - "width": 210, - "height": 104.0, + "x": 1095.0, + "y": 942, + "width": -115.0, + "height": 12, "angle": 0, "strokeColor": "#1e1e1e", "backgroundColor": "transparent", @@ -2640,8 +2640,121 @@ 0 ], [ - 210, - 104.0 + -115.0, + 12 + ] + ], + "lastCommittedPoint": null, + "startBinding": null, + "endBinding": null, + "startArrowhead": null, + "endArrowhead": "arrow", + "elbowed": false + }, + { + "id": "box048", + "x": 40, + "y": 1056, + "width": 1160, + "height": 56, + "angle": 0, + "strokeColor": "#e03131", + "backgroundColor": "#ffe3e3", + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "groupIds": [], + "frameId": null, + "roundness": { + "type": 3 + }, + "seed": 1856033446, + "version": 1, + "versionNonce": 1856033446, + "isDeleted": false, + "boundElements": [ + { + "type": "text", + "id": "box048-text" + } + ], + "updated": 1, + "link": null, + "locked": false, + "type": "rectangle" + }, + { + "id": "box048-text", + "x": 344.17499999999995, + "y": 1073.375, + "width": 551.6500000000001, + "height": 21.25, + "angle": 0, + "strokeColor": "#e03131", + "backgroundColor": "transparent", + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "groupIds": [], + "frameId": null, + "roundness": null, + "seed": 1223482713, + "version": 1, + "versionNonce": 1223482713, + "isDeleted": false, + "boundElements": [], + "updated": 1, + "link": null, + "locked": false, + "type": "text", + "text": "each way of reading a trace tells you half of what was lost", + "originalText": "each way of reading a trace tells you half of what was lost", + "fontSize": 17, + "fontFamily": 1, + "textAlign": "center", + "verticalAlign": "middle", + "containerId": "box048", + "autoResize": true, + "lineHeight": 1.25 + }, + { + "id": "arrow049", + "x": 760, + "y": 982.0, + "width": 440, + "height": 102.0, + "angle": 0, + "strokeColor": "#1e1e1e", + "backgroundColor": "transparent", + "fillStyle": "solid", + "strokeWidth": 2, + "strokeStyle": "solid", + "roughness": 1, + "opacity": 100, + "groupIds": [], + "frameId": null, + "roundness": null, + "seed": 2019468368, + "version": 1, + "versionNonce": 2019468368, + "isDeleted": false, + "boundElements": [], + "updated": 1, + "link": null, + "locked": false, + "type": "arrow", + "points": [ + [ + 0, + 0 + ], + [ + 440, + 102.0 ] ], "lastCommittedPoint": null, @@ -2652,10 +2765,10 @@ "elbowed": false }, { - "id": "note048", + "id": "note050", "x": 40, - "y": 1068, - "width": 815.1, + "y": 1136, + "width": 986.7, "height": 16.25, "angle": 0, "strokeColor": "#5c5f66", @@ -2668,17 +2781,17 @@ "groupIds": [], "frameId": null, "roundness": null, - "seed": 1919075067, + "seed": 3058041375, "version": 1, - "versionNonce": 1919075067, + "versionNonce": 3058041375, "isDeleted": false, "boundElements": [], "updated": 1, "link": null, "locked": false, "type": "text", - "text": "The stats file under per_cpu is the only place that tells you, and the counter to read is named after the setting.", - "originalText": "The stats file under per_cpu is the only place that tells you, and the counter to read is named after the setting.", + "text": "trace_pipe says where and prints no header. The trace file says how many, once, in a header a reader skips, and marks nothing in the body.", + "originalText": "trace_pipe says where and prints no header. The trace file says how many, once, in a header a reader skips, and marks nothing in the body.", "fontSize": 13, "fontFamily": 1, "textAlign": "left", diff --git a/blueprints/assets/trace-ring-buffer-overrun.svg b/blueprints/assets/trace-ring-buffer-overrun.svg index 7d8932d..c5cc699 100644 --- a/blueprints/assets/trace-ring-buffer-overrun.svg +++ b/blueprints/assets/trace-ring-buffer-overrun.svg @@ -1,6 +1,6 @@ - + How a full ring buffer loses events - A picture in four parts, about how a full trace buffer loses events without saying so. Across the top, a ring of four boxes labelled sub buffer 0 to sub buffer 3, joined left to right by arrows with a dashed arrow wrapping from the last one back to the first. The first box is also labelled head, the oldest, the third is labelled tail, writing here now, and a separate box sits outside the ring labelled reader page, off the ring, with a note that the writer will never touch it. Underneath on the left, a column headed what one writer does, with three boxes reading down: read the tail page, read the two timestamps, and add my length to the write index with one atomic add. That last box forks. The left branch is labelled it fits and holds one box reading write the data and commit. The right branch is labelled it does not fit and holds three boxes in a red style reading the next page is the head, throw that whole page away and add its events to overrun, and move the tail onto it. A note beside the red branch says nothing waits, nothing fails, and no caller is told. On the lower left, a small table of the counters as the capture read them, with entries 273, overrun 44002, commit overrun 0 and dropped events 0, and a line under it reading 44275 events written, 99.4% of them thrown away, in 0.007 seconds. On the right, two columns headed the two ways to read a trace. The left column, trace_pipe, has boxes reading consuming read, take overrun minus last overrun, and print CPU:0 LOST 44002 EVENTS. The right column, the trace file, has boxes reading iterator read, ask for the iterator's missed events flag, and a red box reading the writer never sets that bit on an ordinary buffer, so the flag is zero and nothing prints. Across the bottom is a red band reading a quiet trace file is not evidence that nothing was lost, and under it a line saying the stats file under per_cpu is the only place that tells you. + A picture in four parts, about how a full trace buffer loses events without saying so. Across the top, a ring of four boxes labelled sub buffer 0 to sub buffer 3, joined left to right by arrows with a dashed arrow wrapping from the last one back to the first. The first box is also labelled head, the oldest, the third is labelled tail, writing here now, and a separate box sits outside the ring labelled reader page, off the ring, with a note that the writer will never touch it. Underneath on the left, a column headed what one writer does, with three boxes reading down: read the tail page, read the two timestamps, and add my length to the write index with one atomic add. That last box forks. The left branch is labelled it fits and holds one box reading write the data and commit. The right branch is labelled it does not fit and holds three boxes in a red style reading the next page is the head, throw that whole page away and add its events to overrun, and move the tail onto it. A note beside the red branch says nothing waits, nothing fails, and no caller is told. On the lower left, a small table of the counters as the capture read them, with entries 273, overrun 44002, commit overrun 0 and dropped events 0, and a line under it reading 44275 events written, 99.4% of them thrown away, in 0.007 seconds. On the right, two columns headed the two ways to read a trace. The left column, trace_pipe, has boxes reading consuming read, take overrun minus last overrun, and print CPU:0 LOST 44002 EVENTS. The right column, the trace file, has boxes reading iterator read, ask for the iterator's missed events flag, and a red box reading the writer never sets that bit on an ordinary buffer, so nothing marks the body. An arrow leads from that red box to a wide box holding the header line of the trace file, entries-in-buffer slash entries-written 273 slash 44275. Across the bottom is a red band reading each way of reading a trace tells you half of what was lost, and under it a line saying trace_pipe says where and prints no header, while the trace file says how many, once, in a header a reader skips, and marks nothing in the body. @@ -87,13 +87,16 @@ missed events flag the writer never sets that bit, - so the flag is zero + so nothing marks the body - - a quiet trace file is not evidence that nothing was lost - - The stats file under per_cpu is the only place that tells you, and the counter to read is named after the setting. + + the header of the trace file: entries-in-buffer/entries-written 273/44275 + + + each way of reading a trace tells you half of what was lost + + trace_pipe says where and prints no header. The trace file says how many, once, in a header a reader skips, and marks nothing in the body. diff --git a/blueprints/trace-ring-buffer.md b/blueprints/trace-ring-buffer.md index 722701e..fe623e5 100644 --- a/blueprints/trace-ring-buffer.md +++ b/blueprints/trace-ring-buffer.md @@ -19,13 +19,13 @@ artefacts: [proc/tier0/ring-overrun] There is one fact here that changes how you read every trace you will ever take, so it goes first. -A writer into this buffer never blocks, never waits and never fails for lack of room. When the buffer is full it throws the oldest page of events away and carries on. The events are gone, no error is returned to anyone, and the trace file you read afterwards does not say it happened. It starts part way through and looks exactly like a complete trace of a shorter period of time. +A writer into this buffer never blocks, never waits and never fails for lack of room. When the buffer is full it throws the oldest page of events away and carries on. The events are gone, no error is returned to anyone, and the body of the trace file you read afterwards does not say it happened. It starts part way through and reads exactly like a complete trace of a shorter period of time. -The capture in section 5 is that, on purpose. An eight kilobyte buffer, an unfiltered tracer, and about seven thousandths of a second of an idle machine running two small commands. 273 events were still in the buffer. 44002 had been thrown away to make room for them. That is a hundred and sixty one events discarded for every one kept, and the only place any of it is written down is a counter in a file most people never open. +The capture in section 5 is that, on purpose. An eight kilobyte buffer, an unfiltered tracer, and about seven thousandths of a second of an idle machine running two small commands. 273 events were still in the buffer. 44002 had been thrown away to make room for them. That is a hundred and sixty one events discarded for every one kept. -The second fact is why the file goes quiet, and it is not what most people assume. The kernel does know how many events were lost, and it will tell you, over one of the two ways of reading a trace and not the other. `trace_pipe` prints a `CPU:0 [LOST 44002 EVENTS]` line. The `trace` file does not, and section 3 says exactly where the two paths part company. +The second fact is what the two ways of reading a trace will admit, and the answer is that each of them tells you half. The `trace` file prints two numbers in its header, `entries-in-buffer/entries-written`, and on this buffer they would read `273/44275` [trace-ring-buffer-R76]. That is the whole admission: how many, once, at the top, in a header a reader skips on the way to the lines. Nothing in the body of the file marks where the missing events were. `trace_pipe` is the other way round. It prints `CPU:0 [LOST 44002 EVENTS]` at the position the loss happened and has no header at all, so it says where and not how many overall. Section 3 says exactly where the two paths part company, and section 9 says why they were never made to agree. -![A picture in four parts, about how a full trace buffer loses events without saying so. Across the top, a ring of four boxes labelled sub buffer 0 to sub buffer 3, joined left to right by arrows with a dashed arrow wrapping from the last one back to the first. The first box is also labelled head, the oldest, the third is labelled tail, writing here now, and a separate box sits outside the ring labelled reader page, off the ring, with a note that the writer will never touch it. Underneath on the left, a column headed what one writer does, with three boxes reading down: read the tail page, read the two timestamps, and add my length to the write index with one atomic add. That last box forks. The left branch is labelled it fits and holds one box reading write the data and commit. The right branch is labelled it does not fit and holds three boxes in a red style reading the next page is the head, throw that whole page away and add its events to overrun, and move the tail onto it. A note beside the red branch says nothing waits, nothing fails, and no caller is told. On the lower left, a small table of the counters as the capture read them, with entries 273, overrun 44002, commit overrun 0 and dropped events 0, and a line under it reading 44275 events written, 99.4% of them thrown away, in 0.007 seconds. On the right, two columns headed the two ways to read a trace. The left column, trace_pipe, has boxes reading consuming read, take overrun minus last overrun, and print CPU:0 LOST 44002 EVENTS. The right column, the trace file, has boxes reading iterator read, ask for the iterator's missed events flag, and a red box reading the writer never sets that bit on an ordinary buffer, so the flag is zero and nothing prints. Across the bottom is a red band reading a quiet trace file is not evidence that nothing was lost, and under it a line saying the stats file under per_cpu is the only place that tells you.](assets/trace-ring-buffer-overrun.svg) +![A picture in four parts, about how a full trace buffer loses events without saying so. Across the top, a ring of four boxes labelled sub buffer 0 to sub buffer 3, joined left to right by arrows with a dashed arrow wrapping from the last one back to the first. The first box is also labelled head, the oldest, the third is labelled tail, writing here now, and a separate box sits outside the ring labelled reader page, off the ring, with a note that the writer will never touch it. Underneath on the left, a column headed what one writer does, with three boxes reading down: read the tail page, read the two timestamps, and add my length to the write index with one atomic add. That last box forks. The left branch is labelled it fits and holds one box reading write the data and commit. The right branch is labelled it does not fit and holds three boxes in a red style reading the next page is the head, throw that whole page away and add its events to overrun, and move the tail onto it. A note beside the red branch says nothing waits, nothing fails, and no caller is told. On the lower left, a small table of the counters as the capture read them, with entries 273, overrun 44002, commit overrun 0 and dropped events 0, and a line under it reading 44275 events written, 99.4% of them thrown away, in 0.007 seconds. On the right, two columns headed the two ways to read a trace. The left column, trace_pipe, has boxes reading consuming read, take overrun minus last overrun, and print CPU:0 LOST 44002 EVENTS. The right column, the trace file, has boxes reading iterator read, ask for the iterator's missed events flag, and a red box reading the writer never sets that bit on an ordinary buffer, so nothing marks the body. An arrow leads from that red box to a wide box holding the header line of the trace file, entries-in-buffer slash entries-written 273 slash 44275. Across the bottom is a red band reading each way of reading a trace tells you half of what was lost, and under it a line saying trace_pipe says where and prints no header, while the trace file says how many, once, in a header a reader skips, and marks nothing in the body.](assets/trace-ring-buffer-overrun.svg) ## §1 Purpose and boundary @@ -379,7 +379,7 @@ Two things in that table are worth saying in words, because the sizes on their o ## §3 Algorithms -Numbered from the moment something in the kernel decides to record an event. Steps 1 to 12 are one writer putting one record in. Steps 13 to 16 are what happens when it does not fit, which is where the events go. Steps 17 to 21 are a reader taking pages out, and the last two of those are where the two ways of reading a trace stop agreeing with each other. +Numbered from the moment something in the kernel decides to record an event. Steps 1 to 12 are one writer putting one record in. Steps 13 to 16 are what happens when it does not fit, which is where the events go. Steps 17 to 22 are a reader taking pages out, and the last three of those are where the two ways of reading a trace stop agreeing with each other. 1. Turn off preemption and test four things, in order [trace-ring-buffer-R15]. Recording disabled for the whole buffer, this processor not being one the buffer has a per processor area for, recording disabled for this processor alone, and a length larger than the biggest record the buffer can hold [trace-ring-buffer-R16]. Any of the four returns a null pointer. The caller is expected to check it and give up, and nothing counts how often that happened. @@ -423,7 +423,9 @@ Numbered from the moment something in the kernel decides to record an event. Ste 20. A consuming read takes that number with it [trace-ring-buffer-R57]. This is what `trace_pipe` uses, and it is why `trace_pipe` can print a line saying how many events it missed [trace-ring-buffer-R63]. -21. An iterating read asks a different question [trace-ring-buffer-R58]. It calls a function that reports whether the iterator has a missed events flag set [trace-ring-buffer-R59], and that flag has exactly one place it is ever set from, which is a bit in a page's commit field [trace-ring-buffer-R60]. On an ordinary buffer the writer never sets that bit. The kernel says so in a comment next to the one place that does set it [trace-ring-buffer-R61], which is a persistent buffer being recovered across a reboot [trace-ring-buffer-R62]. So on the machine in section 5 the flag is zero, the count is never consulted, and the `trace` file prints no line about the 44002 events that are gone. +21. An iterating read asks a different question [trace-ring-buffer-R58]. It calls a function that reports whether the iterator has a missed events flag set [trace-ring-buffer-R59], and that flag has exactly one place it is ever set from, which is a bit in a page's commit field [trace-ring-buffer-R60]. On an ordinary buffer the writer never sets that bit. The kernel says so in a comment next to the one place that does set it [trace-ring-buffer-R61], which is a persistent buffer being recovered across a reboot [trace-ring-buffer-R62]. So on the machine in section 5 the flag is zero, the count is never consulted, and nothing in the body of the `trace` file marks the place where the 44002 events were. + +22. The `trace` file gets its number from somewhere else entirely, and this is the step that stops the previous one being read as the whole story. The header of that file is printed by the same seq_file machinery that prints the lines [trace-ring-buffer-R76], and the second of its two numbers is not a counter at all: it is this processor's kept events plus this processor's overrun, added up at the moment the header is printed [trace-ring-buffer-R77]. So the file does say how many are missing, once, at the top, and never says where. That header is also a display option rather than part of the format, and turning `context-info` off removes it [trace-ring-buffer-R78]. ## §4 Invariants, locking and context @@ -441,7 +443,7 @@ Numbered from the moment something in the kernel decides to record an event. Ste 10. The number of events lost between two consuming reads equals the difference in the overrun counter across them [trace-ring-buffer-R55]. [checked: the reader records the counter under the same lock and page ownership it does the swap under] 11. On an ordinary buffer, an iterating reader's missed events flag is always zero [trace-ring-buffer-R61]. [unchecked] -Invariant 11 is the one this blueprint exists to write down. Nothing in the kernel enforces it, nothing tests it, and it is not stated anywhere except in a comment about a different case. It is the difference between a trace file that is quiet because nothing was lost and a trace file that is quiet because nobody asked. +Invariant 11 is the one this blueprint exists to write down. Nothing in the kernel enforces it, nothing tests it, and it is not stated anywhere except in a comment about a different case. It is why the body of a trace file reads the same whether nothing was lost or almost everything was, and why the only thing that separates those two cases is a pair of numbers in the header and a counter in another file. ### §4b Locking discipline @@ -542,7 +544,7 @@ The other one is the pair of counters that look like they mean the same thing. ` - **hostile-input.** Nothing here reads anything from userspace. The steering an unprivileged program can do is on the workload rather than on the mechanism, and it is significant: on a machine where tracing is on, a program that generates events quickly pushes everything else out of the buffer, and there is no fairness of any kind between the things being traced. A trace taken during a noisy workload is a trace of the noisy workload. -- **bug-message.** This mechanism prints almost nothing. Its warnings are internal consistency checks that fire when the structure it walks has come apart, and each of them switches nothing off and carries on. The two ceilings that produce one are the thousand retry limit in the reserve [trace-ring-buffer-R24] and the bounded commit walk [trace-ring-buffer-R73]. Neither is a message about the code being traced. The message a person actually wants, which is that events were lost, is not a warning at all: it is a counter [trace-ring-buffer-R42] and, on one of the two read paths, one line of output [trace-ring-buffer-R63]. +- **bug-message.** This mechanism prints almost nothing. Its warnings are internal consistency checks that fire when the structure it walks has come apart, and each of them switches nothing off and carries on. The two ceilings that produce one are the thousand retry limit in the reserve [trace-ring-buffer-R24] and the bounded commit walk [trace-ring-buffer-R73]. Neither is a message about the code being traced. The message a person actually wants, which is that events were lost, is not a warning at all. It is a counter [trace-ring-buffer-R42], two numbers in a header a reader skips [trace-ring-buffer-R76], and on one of the two read paths one line of output at the place it happened [trace-ring-buffer-R63]. ## §7 Interfaces @@ -640,7 +642,7 @@ Choices Linux made that another kernel could make differently: - **Not telling the writer** [trace-ring-buffer-R42]. The reserve returns a valid pointer on the path where a whole page was thrown out. The writer that caused the loss is never told, and neither is the writer whose events were lost, since it finished long ago. A kernel could return a flag on the reserve, which would cost a branch on the hottest path in the tracer to deliver news that no caller could act on anyway. Linux put it in a counter, and the cost of that is section 5. -- **Two read paths that answer differently** [trace-ring-buffer-R57] [trace-ring-buffer-R58]. The consuming reader has an exact count of lost events and the iterating reader has a flag that is never set. That is not a design somebody sat down and chose, it is two mechanisms that grew separately, and the result is that the same buffer read two ways tells you two different things about whether it is complete. A kernel starting fresh would give both readers the same answer, and doing it here would cost the writer nothing, because the number the iterator would need is already being maintained. +- **Two read paths, each of which tells you half** [trace-ring-buffer-R57] [trace-ring-buffer-R58]. The consuming reader carries an exact count out to the place the loss happened and prints it there [trace-ring-buffer-R63], and has no header. The iterating reader has a flag that is never set, so it marks nothing in the body, and its file prints a total in a header computed separately from the same counters [trace-ring-buffer-R77]. Neither of them gives a reader both numbers. That is not a design somebody sat down and chose, it is two mechanisms that grew separately, and the result is that the same buffer read two ways is described two different ways. A kernel starting fresh would give both readers both answers, and doing it here would cost the writer nothing, because everything either of them would need is already being maintained. - **Tagging pointers with the state of a lockless protocol** [trace-ring-buffer-R47]. It costs no memory and it makes the compare and swap that moves the head atomic with the check that it is the head. The price is that the head pointer cannot be trusted on its own [trace-ring-buffer-R49] and every piece of code that walks the list has to mask the bits off, which is a class of bug that does not exist in an implementation with a separate state word. A kernel could keep the state in the page structure instead and accept a second atomic. diff --git a/blueprints/trace-ring-buffer.refs.toml b/blueprints/trace-ring-buffer.refs.toml index 66f9a2a..89b0255 100644 --- a/blueprints/trace-ring-buffer.refs.toml +++ b/blueprints/trace-ring-buffer.refs.toml @@ -775,3 +775,33 @@ confirmed = true line = 75 context = "b85c7a9ac9c7" note = "The event header layout is printed to userspace by hand from this function, so a tool reading the raw pages gets the field widths from the kernel rather than from a header file." + +[[references]] +id = "trace-ring-buffer-R76" +path = "kernel/trace/trace.c" +anchor = "entries-in-buffer/entries-written: %lu/%lu" +kernel = "7.2.2" +confirmed = true +line = 2903 +context = "88777f889ebd" +note = "The one place the trace file admits to losing anything. Two numbers in the header, how many are here and how many were written, and no mark anywhere in the body." + +[[references]] +id = "trace-ring-buffer-R77" +path = "kernel/trace/trace.c" +anchor = "ring_buffer_overrun_cpu(buf->buffer, cpu);" +kernel = "7.2.2" +confirmed = true +line = 2839 +context = "779961ff472b" +note = "The second of those two numbers is kept events plus overrun, added up when the header is printed, so it is a total worked out at read time rather than a counter the writer keeps." + +[[references]] +id = "trace-ring-buffer-R78" +path = "kernel/trace/trace.c" +anchor = "if (!(trace_flags & TRACE_ITER(CONTEXT_INFO)))" +kernel = "7.2.2" +confirmed = true +line = 3262 +context = "3c123b9d6973" +note = "The header is a display option rather than part of the format, so turning context-info off removes the only admission the trace file makes."