diff --git a/README.md b/README.md index c62f871..94eb496 100644 --- a/README.md +++ b/README.md @@ -78,23 +78,21 @@ happened and *for how long*, which puts a call visibly inside the one which made it. The bar sits on a rail rather than on empty space, so its position is readable even where the colour is not. -Colour and weight come from **self** time — how long a function took minus how -long the functions it called took. That distinction is what makes the page -useful: a framework's kernel and dispatch frames wrap the whole request, so -colouring by elapsed time paints them all at maximum severity while the function -actually burning the time stays cool. Ordering is chronological and severity is -self time, so the hotspot is still the heaviest mark on the page wherever in the -sequence it falls. - -Self time is an upper bound rather than a measurement. The extension only fires -a probe for calls above `compass.function_threshold`, so a child cheaper than -the threshold is missing from the tree and its time is counted against its -parent. Lower the threshold if a frame looks suspiciously hot. +Colour and weight come from elapsed call duration as a share of the whole +request. A call which runs for 400ms during a 1s request reads as 40%; the same +share drives the percentage, the colour, and the gutter weight. Ordering stays +chronological, so nested callers and callees remain visible in the sequence in +which they ran. + +The extension only fires a probe for calls above +`compass.function_threshold`, so the page is not an exhaustive call tree. Lower +the threshold when shorter calls are relevant. The sidecar retains at most `COMPASS_SIDECAR_MAX_FUNCTION_CALLS` calls per trace. -When a request exceeds that bound, Search adds `+` to its retained call count, -the open trace reports the exact number dropped, and **self*** marks timing -derived from retained calls only. Peak memory still includes later dropped calls. +When a request exceeds that bound, Search adds `+` to its retained call count +and the open trace reports the exact number dropped. The elapsed duration of +each retained call remains a direct measurement. Peak memory still includes +later dropped calls. **Drupal Cacheable Metadata** is what the Drupal specific probes reported. The tab only appears when the trace has any: a Node trace, a PHP CLI run and any PHP @@ -111,8 +109,8 @@ through the detail, rather than something you do and then look elsewhere for. On **Functions** that is the whole name, which the table shortens to namespace initials and then truncates, along with the numbers behind the two columns which -are a percentage and a picture: what the self share is in milliseconds, and -where in the request the call sat. On **Drupal Cacheable Metadata** it is the +are a percentage and a picture: the call's elapsed duration as a share of the +request, and where in the request the call sat. On **Drupal Cacheable Metadata** it is the cache tags and contexts, which the table only counts, and the object's full class name — the namespace being exactly what says which module it came from. diff --git a/pkg/app/component/span/span.go b/pkg/app/component/span/span.go index 343a4b1..94829ac 100644 --- a/pkg/app/component/span/span.go +++ b/pkg/app/component/span/span.go @@ -1,11 +1,7 @@ // Package span renders a function call as a bar on a request's timeline. // -// A bar carries three independent facts, in three independent channels: where -// in the request the call happened (position), how long it ran for (length), -// and how much of the request it was itself responsible for (colour). Keeping -// them separate is the point — the previous version coloured by length, which -// meant every frame that merely wrapped the request rendered at maximum -// severity while the function actually burning the time rendered cool. +// A bar carries two elapsed-time facts: where in the request the call happened +// (position), and how long it ran for (length and colour). package span import ( @@ -43,11 +39,6 @@ type Span struct { Start time.Duration // Duration the call ran for. Duration time.Duration - // Share of the request the call is itself responsible for, from zero to - // one. This drives the colour, and it is deliberately not derived from - // Duration: a call which delegates all of its time to a child is long but - // not hot. - Share float64 } // Bar is a span's parts, kept apart rather than rendered into one string. @@ -63,7 +54,7 @@ type Bar struct { Fill string // Trail is the track after the span ends. Trail string - // Share the fill should be coloured by. + // Share of the request occupied by the fill's elapsed duration. Share float64 } @@ -93,7 +84,7 @@ func (c *Component) Bar(s Span) Bar { Lead: run(theme.RuleLight, from), Fill: run(theme.BarFull, to-from), Trail: run(theme.RuleLight, c.Blocks-to), - Share: s.Share, + Share: FractionDuration(s.Duration, c.Duration), } } @@ -127,7 +118,7 @@ func (c *Component) Render(s Span) string { bar := c.Bar(s) var ( - fill = theme.S.Ramp(s.Share) + fill = theme.S.Ramp(bar.Share) track = theme.S.Track ) diff --git a/pkg/app/component/span/span_test.go b/pkg/app/component/span/span_test.go index 6fed124..563fe93 100644 --- a/pkg/app/component/span/span_test.go +++ b/pkg/app/component/span/span_test.go @@ -90,20 +90,20 @@ func TestComponent_Render_PositionIsVisible(t *testing.T) { assert.NotEqual(t, early, late) } -// Colour comes from the share, not the length. This is the inversion the -// rewrite exists to fix: a frame which wraps the whole request but does none -// of the work must not render hotter than the function doing the work. -func TestComponent_Render_ColourFollowsShareNotLength(t *testing.T) { +// Colour follows elapsed duration as a share of the whole request, just like +// the percentage and gutter weight on the Functions page. +func TestComponent_Render_ColourFollowsDuration(t *testing.T) { c := New(100*time.Millisecond, 40) - wrapper := c.Render(Span{Start: 0, Duration: 100 * time.Millisecond, Share: 0.01}) - hotspot := c.Render(Span{Start: 40 * time.Millisecond, Duration: 20 * time.Millisecond, Share: 0.9}) + short := c.Render(Span{Start: 0, Duration: 10 * time.Millisecond}) + long := c.Render(Span{Start: 0, Duration: 90 * time.Millisecond}) - assert.NotEqual(t, colourOf(t, wrapper), colourOf(t, hotspot)) + assert.NotEqual(t, colourOf(t, short), colourOf(t, long)) - // Two spans of very different lengths but the same share agree on colour. - short := c.Render(Span{Start: 0, Duration: 5 * time.Millisecond, Share: 0.9}) - assert.Equal(t, colourOf(t, hotspot), colourOf(t, short)) + // Position is a separate fact: equal durations at opposite ends of the + // request use the same colour. + late := c.Render(Span{Start: 80 * time.Millisecond, Duration: 10 * time.Millisecond}) + assert.Equal(t, colourOf(t, short), colourOf(t, late)) } func TestComponent_Axis_IsExactlyBlocksWide(t *testing.T) { diff --git a/pkg/app/functions.go b/pkg/app/functions.go index 7364c49..09c6f3e 100644 --- a/pkg/app/functions.go +++ b/pkg/app/functions.go @@ -14,7 +14,7 @@ import ( // Widths of the functions columns. const ( - functionsWidthSelf = 6 + functionsWidthShare = 6 functionsWidthMemory = 10 functionsWidthTimeline = 44 functionsWidthElapsed = 8 @@ -41,14 +41,9 @@ func (m *Model) functionsInit() { } func (m *Model) functionsSetColumns() { - selfTitle := "self" - if m.Current != nil && m.Current.FunctionCallsDropped > 0 { - selfTitle += PartialTimingMarker - } - m.functions.SetColumns([]datatable.Column{ {Title: "function", Flex: 1, MinWidth: functionsMinName}, - {Title: selfTitle, Width: functionsWidthSelf, Align: datatable.AlignRight}, + {Title: "share", Width: functionsWidthShare, Align: datatable.AlignRight}, {Title: "mem (inc)", Width: functionsWidthMemory, Align: datatable.AlignRight, Priority: functionsPriorityMemory}, {Title: m.timelineTitle(), Width: functionsWidthTimeline, Priority: functionsPriorityTimeline}, {Title: "elapsed", Width: functionsWidthElapsed, Align: datatable.AlignRight, Priority: functionsPriorityElapsed}, @@ -116,7 +111,7 @@ func (m *Model) functionsSetRows() { for _, index := range m.functionVisible { s := spans[index] - share := s.SelfShare(executionTime) + share := s.DurationShare(executionTime) rows = append(rows, datatable.Row{ functionNameCell(s), @@ -125,7 +120,6 @@ func (m *Model) functionsSetRows() { timelineCell(timeline.Bar(span.Span{ Start: s.Offset, Duration: s.Length, - Share: share, })), datatable.Styled(format.Duration(s.Length), theme.S.CellDim), }) @@ -204,10 +198,10 @@ func (m *Model) functionsInspectLines() []string { executionTime := m.Current.Metadata.ExecutionTime() - self := fmt.Sprintf("%s of %s %s", - format.Duration(span.SelfTime), + duration := fmt.Sprintf("%s of %s %s", + format.Duration(span.Length), format.Duration(executionTime), - format.Percent(span.SelfShare(executionTime)), + format.Percent(span.DurationShare(executionTime)), ) window := fmt.Sprintf("%s in, ran for %s %s", @@ -216,18 +210,9 @@ func (m *Model) functionsInspectLines() []string { format.Count(span.TotalFunctionCalls, "call", "calls"), ) - lines := []string{ + return []string{ m.inspectValue("function", span.Name), - m.inspectValue("self", self), + m.inspectValue("share", duration), m.inspectValue("window", window), } - - if m.Current.FunctionCallsDropped > 0 { - lines = append(lines, m.inspectValue("data", fmt.Sprintf( - "partial · %d calls dropped · self time uses retained calls only", - m.Current.FunctionCallsDropped, - ))) - } - - return lines } diff --git a/pkg/app/help.go b/pkg/app/help.go index bcd7046..626e4e7 100644 --- a/pkg/app/help.go +++ b/pkg/app/help.go @@ -39,15 +39,13 @@ func (m *Model) viewHelp() string { {theme.SelectionRail, "the row the cursor is on"}, {AttentionMarker, "uncacheable: something set a max age of zero"}, {TruncatedMarker, "after calls: additional function calls were dropped"}, - {PartialTimingMarker, "derived timing uses retained function calls only"}, }, }, { - title: "Self", + title: "Duration", rows: [][2]string{ - {"", "the share of a request a function spent on its own work,"}, - {"", "not waiting on what it called. Reads high: calls under the"}, - {"", "extension's threshold are not recorded."}, + {"", "the elapsed call duration as a share of the whole request."}, + {"", "It drives the percentage, colour, and gutter weight."}, }, }, } diff --git a/pkg/app/search.go b/pkg/app/search.go index bc639a6..4cb6138 100644 --- a/pkg/app/search.go +++ b/pkg/app/search.go @@ -183,13 +183,8 @@ func idCell(t events.Trace) datatable.Cell { return datatable.Styled(shortID(t.Metadata.ID), theme.S.CellDim) } -// Markers for partial function-call data. -const ( - // TruncatedMarker after a call count means additional calls were dropped. - TruncatedMarker = "+" - // PartialTimingMarker means derived timing uses retained calls only. - PartialTimingMarker = "*" -) +// TruncatedMarker after a call count means additional calls were dropped. +const TruncatedMarker = "+" // functionCallCount reports retained calls and marks partial traces. func functionCallCount(t events.Trace) string { diff --git a/pkg/app/theme/palette_test.go b/pkg/app/theme/palette_test.go index 781e767..144d4aa 100644 --- a/pkg/app/theme/palette_test.go +++ b/pkg/app/theme/palette_test.go @@ -185,8 +185,8 @@ func TestSelectedBandIsVisibleAndCarriesItsRow(t *testing.T) { } } -// The ramp colours text as well as bars — a duration and a self share are both -// rendered in it — so every stop has to be readable, not just the hot end. +// The ramp colours text as well as bars — elapsed duration share is rendered +// in both — so every stop has to be readable, not just the hot end. func TestWholeRampIsLegible(t *testing.T) { black := mustColour(t, ground) diff --git a/pkg/app/theme/severity.go b/pkg/app/theme/severity.go index f9b72a1..e0b5405 100644 --- a/pkg/app/theme/severity.go +++ b/pkg/app/theme/severity.go @@ -55,7 +55,7 @@ func ForDurationMs(ms int64) Severity { } } -// Self share thresholds, at the top of each level. +// Request share thresholds, at the top of each level. const ( ShareNone = 0.05 ShareTrace = 0.10 @@ -65,12 +65,8 @@ const ( ShareHigh = 0.60 ) -// ForShare is the severity of the fraction of a request a function is itself -// responsible for. -// -// The scale is much steeper than a wall clock one because self time is -// concentrated: in a healthy request almost every frame is near zero, so a -// function holding a quarter of the total is already the answer. +// ForShare is the severity of the fraction of a request occupied by a +// function call's elapsed duration. func ForShare(share float64) Severity { switch { case share < ShareNone: diff --git a/pkg/app/view_test.go b/pkg/app/view_test.go index 77ae788..2e85912 100644 --- a/pkg/app/view_test.go +++ b/pkg/app/view_test.go @@ -316,9 +316,8 @@ func TestFunctions_OrderedByExecution(t *testing.T) { Source: trace.SourceHTTP, StartTime: at(0), EndTime: at(1_000_000_000), }, FunctionCalls: []trace.FunctionCall{ - // Deliberately out of order, and with the hottest last, so that - // neither insertion order nor self time could produce this result - // by accident. + // Deliberately out of order, with the longest call in the middle, + // so insertion order and duration ranking both differ from this. {Name: "third", Offset: 600_000_000, Elapsed: 100_000_000}, {Name: "first", Offset: 100_000_000, Elapsed: 50_000_000}, {Name: "second", Offset: 300_000_000, Elapsed: 500_000_000}, @@ -350,9 +349,9 @@ func TestFunctions_CallerBeforeCallee(t *testing.T) { assert.Equal(t, []string{"parent", "child"}, functionNames(m)) } -// Ordering by time is not the same as ranking by it: the hotspot still has to -// be findable, which is what the self column is for. -func TestFunctions_HotspotIsFindableOutOfOrder(t *testing.T) { +// Ordering by time is not the same as ranking by it: the share column keeps the +// elapsed cost visible without taking the call sequence apart. +func TestFunctions_DurationShareFollowsElapsedTime(t *testing.T) { m := testModel(120, 40) m.Current = &events.Trace{Trace: trace.Trace{ @@ -360,37 +359,31 @@ func TestFunctions_HotspotIsFindableOutOfOrder(t *testing.T) { Source: trace.SourceHTTP, StartTime: at(0), EndTime: at(1_000_000_000), }, FunctionCalls: []trace.FunctionCall{ - // A frame which wraps the whole request but does none of the work, - // and the function actually burning the time underneath it. {Name: "wrapper", Offset: 0, Elapsed: 1_000_000_000}, - {Name: "hotspot", Offset: 100_000_000, Elapsed: 800_000_000}, + {Name: "child", Offset: 100_000_000, Elapsed: 200_000_000}, }, }} m.functionsSetRows() - require.Equal(t, []string{"wrapper", "hotspot"}, functionNames(m)) + require.Equal(t, []string{"wrapper", "child"}, functionNames(m)) rows := m.functions.Rows() + assert.Equal(t, "100.0%", rows[0][shareColumn].String()) + assert.Equal(t, "20.0%", rows[1][shareColumn].String()) - // The wrapper is the longer call and comes first, but the hotspot is the - // one the self column points at. The wrapper keeps the 200ms it spent - // outside the child, which is the point: self time is what it did itself, - // not nothing. - assert.Equal(t, "20.0%", rows[0][selfColumn].String(), "the wrapper's own time") - assert.Equal(t, "80.0%", rows[1][selfColumn].String(), "the hotspot's own time") - - // And they are not the same colour, so it is visible as well as readable. + // Percentage severity uses the same duration share, so the wrapper is also + // visibly hotter than the shorter child. assert.NotEqual(t, - rows[0][selfColumn].Segments[0].Style.Render("x"), - rows[1][selfColumn].Segments[0].Style.Render("x"), + rows[0][shareColumn].Segments[0].Style.Render("x"), + rows[1][shareColumn].Segments[0].Style.Render("x"), ) } // Column positions on the functions page, for the tests which read a cell. const ( functionColumn = 0 - selfColumn = 1 + shareColumn = 1 ) // functionNames of the rows on the functions page, in the order shown. @@ -417,7 +410,7 @@ func TestView_HelpMarksWhereItWasCut(t *testing.T) { view := ansi.Strip(tall.View()) assert.NotContains(t, view, "more, on a taller terminal") - assert.Contains(t, view, "SELF", "the whole legend should fit a terminal this tall") + assert.Contains(t, view, "DURATION", "the whole legend should fit a terminal this tall") } // The marker fires for one reason only. A mark which means two different things @@ -686,7 +679,7 @@ func TestFunctions_InspectShowsTheSelectedRowInFull(t *testing.T) { assert.Contains(t, panel, `Drupal\Core\DrupalKernel::handle`) assert.Contains(t, panel, "function") - assert.Contains(t, panel, "self") + assert.Contains(t, panel, "share") assert.Contains(t, panel, "window") // And it follows the cursor. @@ -698,8 +691,8 @@ func TestFunctions_InspectShowsTheSelectedRowInFull(t *testing.T) { assert.NotContains(t, panel, "DrupalKernel") } -// The self column is a percentage and the timeline is a picture. Neither says -// how long anything actually took, which is what the panel is for. +// The share column is a percentage and the timeline is a picture. The panel +// gives the elapsed durations behind both. func TestFunctions_InspectGivesTheNumbersBehindTheColumns(t *testing.T) { m := testModel(120, 34) m.updateKeyEnter() @@ -708,7 +701,9 @@ func TestFunctions_InspectGivesTheNumbersBehindTheColumns(t *testing.T) { panel := ansi.Strip(m.inspectView()) // renderRoot ran from 100ms to 250ms of a 402ms request. + assert.Contains(t, panel, "share") assert.Contains(t, panel, "150ms") + assert.Contains(t, panel, "37.3%") assert.Contains(t, panel, "100ms in") assert.Contains(t, panel, "402ms") } @@ -790,7 +785,7 @@ func TestView_PanelDoesNotRunIntoTheKeyRail(t *testing.T) { "the key rail should sit under a rule, not under the panel's last value") } -func TestFunctionTruncation_IsVisibleAndDerivedTimingIsMarkedPartial(t *testing.T) { +func TestFunctionTruncation_IsVisibleWithoutQualifyingDurationShare(t *testing.T) { m := testModel(120, 34) partial := testTrace("/partial") @@ -811,21 +806,21 @@ func TestFunctionTruncation_IsVisibleAndDerivedTimingIsMarkedPartial(t *testing. columns := m.functions.Columns() require.GreaterOrEqual(t, len(columns), 2) - assert.Equal(t, "self*", columns[1].Title) + assert.Equal(t, "share", columns[1].Title) inspect := ansi.Strip(m.inspectView()) - assert.Contains(t, inspect, "7 calls dropped") - assert.Contains(t, inspect, "self time uses retained calls only") + assert.NotContains(t, inspect, "calls dropped") + assert.NotContains(t, inspect, "retained calls only") } -func TestFunctionTruncation_CleanTraceHasNoPartialMarkers(t *testing.T) { +func TestFunctionTruncation_CleanTraceUsesTheSameShareColumn(t *testing.T) { m := testModel(120, 34) m.updateKeyEnter() assert.NotContains(t, ansi.Strip(m.viewDetail()), "CALL DATA") columns := m.functions.Columns() require.GreaterOrEqual(t, len(columns), 2) - assert.Equal(t, "self", columns[1].Title) + assert.Equal(t, "share", columns[1].Title) assert.NotContains(t, ansi.Strip(m.inspectView()), "retained calls only") } @@ -835,7 +830,8 @@ func TestFunctionTruncation_IsExplainedInHelp(t *testing.T) { help := ansi.Strip(m.viewHelp()) assert.Contains(t, help, "additional function calls were dropped") - assert.Contains(t, help, "derived timing uses retained function calls only") + assert.Contains(t, help, "elapsed call duration as a share") + assert.NotContains(t, help, "derived timing") } func TestFilter_FunctionsNarrowsRowsAndInspectFollowsSelection(t *testing.T) { diff --git a/pkg/trace/segmented/self.go b/pkg/trace/segmented/self.go deleted file mode 100644 index f528e8d..0000000 --- a/pkg/trace/segmented/self.go +++ /dev/null @@ -1,95 +0,0 @@ -package segmented - -import ( - "sort" - "time" - - "github.com/skpr/compass/pkg/trace" -) - -// SelfTime of each function call, keyed by its index in the given slice. -// -// Self time is how long a call ran for minus how long its direct children ran -// for: the time the function actually spent doing its own work. It is the -// number worth colouring a timeline by. Inclusive time is not — every frame -// which merely wraps the request has almost all of it, so ranking by inclusive -// time puts the kernel at the top and the hotspot in the middle. -// -// The nesting is recovered by containment rather than being recorded: a call -// whose interval sits inside another's was called by it. Sorting by start, and -// by descending length where two calls start together, walks the stack in the -// order the request did. -// -// # Accuracy -// -// The probe only fires for calls above the extension's threshold, so the tree -// is incomplete: a child cheaper than the threshold is missing, and its time is -// counted against its parent. Self time is therefore an upper bound rather than -// a measurement, and the error on any one frame is bounded by the threshold -// times the number of calls hidden beneath it. It is still far closer to the -// truth than inclusive time, which is wrong by design. -func SelfTime(calls []trace.FunctionCall) []time.Duration { - self := make([]time.Duration, len(calls)) - - for i, call := range calls { - self[i] = call.Elapsed - } - - order := make([]int, len(calls)) - for i := range order { - order[i] = i - } - - sort.SliceStable(order, func(a, b int) bool { - left, right := calls[order[a]], calls[order[b]] - - if left.Offset != right.Offset { - return left.Offset < right.Offset - } - - // A parent starting at the same instant as its child has to come first, - // and it is the longer of the two. - return left.Elapsed > right.Elapsed - }) - - // The stack holds the calls still open, outermost first. - var stack []int - - for _, index := range order { - call := calls[index] - end := call.Offset + call.Elapsed - - for len(stack) > 0 { - open := calls[stack[len(stack)-1]] - - if open.Offset+open.Elapsed > call.Offset { - break - } - - stack = stack[:len(stack)-1] - } - - if len(stack) > 0 { - parent := stack[len(stack)-1] - - // Only the part of the child inside the parent counts against it. - // Threshold filtering and aggregation can produce intervals which - // overhang, and charging a parent for time after it returned would - // take its self time negative. - overlap := min(end, calls[parent].Offset+calls[parent].Elapsed) - call.Offset - if overlap > 0 { - self[parent] -= overlap - } - } - - stack = append(stack, index) - } - - for i := range self { - if self[i] < 0 { - self[i] = 0 - } - } - - return self -} diff --git a/pkg/trace/segmented/self_test.go b/pkg/trace/segmented/self_test.go deleted file mode 100644 index 42fdbf8..0000000 --- a/pkg/trace/segmented/self_test.go +++ /dev/null @@ -1,191 +0,0 @@ -package segmented - -import ( - "testing" - "time" - - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - - "github.com/skpr/compass/pkg/trace" -) - -func call(name string, offset, elapsed time.Duration) trace.FunctionCall { - return trace.FunctionCall{Name: name, Offset: offset, Elapsed: elapsed} -} - -func TestSelfTime_NoCalls(t *testing.T) { - assert.Empty(t, SelfTime(nil)) -} - -func TestSelfTime_SingleCall(t *testing.T) { - assert.Equal(t, []time.Duration{100}, SelfTime([]trace.FunctionCall{call("a", 0, 100)})) -} - -func TestSelfTime_Siblings(t *testing.T) { - // Two calls which do not nest each keep all of their time. - self := SelfTime([]trace.FunctionCall{ - call("a", 0, 30), - call("b", 40, 20), - }) - - assert.Equal(t, []time.Duration{30, 20}, self) -} - -func TestSelfTime_ParentAndChild(t *testing.T) { - self := SelfTime([]trace.FunctionCall{ - call("parent", 0, 100), - call("child", 10, 60), - }) - - assert.Equal(t, []time.Duration{40, 60}, self) -} - -func TestSelfTime_OnlyDirectChildrenAreDeducted(t *testing.T) { - // The grandchild's time is already inside the child's, so deducting it from - // the parent as well would count it twice. - self := SelfTime([]trace.FunctionCall{ - call("parent", 0, 100), - call("child", 10, 80), - call("grandchild", 20, 50), - }) - - assert.Equal(t, []time.Duration{20, 30, 50}, self) -} - -func TestSelfTime_MultipleChildren(t *testing.T) { - self := SelfTime([]trace.FunctionCall{ - call("parent", 0, 100), - call("first", 0, 30), - call("second", 40, 40), - }) - - assert.Equal(t, []time.Duration{30, 30, 40}, self) -} - -// A parent which starts at the same instant as its child has to be recognised -// as the parent, which is what the length tiebreak is for. -func TestSelfTime_SharedStart(t *testing.T) { - self := SelfTime([]trace.FunctionCall{ - call("child", 0, 40), - call("parent", 0, 100), - }) - - assert.Equal(t, []time.Duration{40, 60}, self) -} - -func TestSelfTime_OrderOfInputDoesNotMatter(t *testing.T) { - forwards := SelfTime([]trace.FunctionCall{ - call("parent", 0, 100), - call("child", 10, 60), - }) - - backwards := SelfTime([]trace.FunctionCall{ - call("child", 10, 60), - call("parent", 0, 100), - }) - - assert.Equal(t, forwards[0], backwards[1]) - assert.Equal(t, forwards[1], backwards[0]) -} - -// The call tree is incomplete, because the probe only fires above a threshold, -// so intervals can overhang their parent. Self time must never go negative. -func TestSelfTime_NeverNegative(t *testing.T) { - self := SelfTime([]trace.FunctionCall{ - call("parent", 0, 50), - call("overhanging child", 10, 500), - }) - - for i, value := range self { - assert.GreaterOrEqual(t, value, time.Duration(0), "call %d", i) - } -} - -// The case from the screenshot in the repository, which is what motivated all -// of this: a stack of framework frames that each wrap the whole request, and -// one function underneath doing the actual work. Ranking by elapsed puts the -// framework on top; ranking by self time finds the hotspot. -func TestSelfTime_FindsTheHotspotUnderTheFramework(t *testing.T) { - calls := []trace.FunctionCall{ - call(`Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher::dispatch`, 0, 6293), - call(`Symfony\Component\HttpKernel\HttpKernel::terminate`, 0, 6293), - call(`Drupal\Core\Cron::run`, 1, 6284), - call(`Drupal\Core\Cron::invokeCronHandlers`, 2, 6282), - call("search_cron", 3, 4379), - call(`Drupal\help\Plugin\Search\HelpSearch::updateIndex`, 4, 3047), - } - - self := SelfTime(calls) - - hottest := 0 - for i := range self { - if self[i] > self[hottest] { - hottest = i - } - } - - require.Equal(t, `Drupal\help\Plugin\Search\HelpSearch::updateIndex`, calls[hottest].Name, - "self time should rank the hotspot first, not the frames wrapping it") - - // And the frames which merely wrap it are nearly free. - assert.Less(t, self[0], 10*time.Nanosecond) - assert.Less(t, self[1], 10*time.Nanosecond) -} - -func TestUnmarshal_CarriesSelfTime(t *testing.T) { - segmentedTrace := Unmarshal(trace.Trace{ - Metadata: trace.Metadata{StartTime: at(0), EndTime: at(1000)}, - FunctionCalls: []trace.FunctionCall{ - call("parent", 0, 1000), - call("child", 100, 600), - }, - }, 50) - - byName := make(map[string]Span) - for _, span := range segmentedTrace.Spans { - byName[span.Name] = span - } - - assert.Equal(t, 400*time.Nanosecond, byName["parent"].SelfTime) - assert.Equal(t, 600*time.Nanosecond, byName["child"].SelfTime) - assert.InDelta(t, 0.6, byName["child"].SelfShare(1000), 0.001) -} - -// Repeated calls to the same function aggregate into one span when they land -// in the same segment, and their self time adds up rather than one winning. -func TestUnmarshal_AggregatesSelfTime(t *testing.T) { - // A thousand nanoseconds over fifty segments is twenty per segment, so both - // of these fall in the first one. - segmentedTrace := Unmarshal(trace.Trace{ - Metadata: trace.Metadata{StartTime: at(0), EndTime: at(1000)}, - FunctionCalls: []trace.FunctionCall{ - call("repeated", 0, 10), - call("repeated", 11, 10), - }, - }, 50) - - require.Len(t, segmentedTrace.Spans, 1) - assert.Equal(t, 20*time.Nanosecond, segmentedTrace.Spans[0].SelfTime) - assert.Equal(t, 2, segmentedTrace.Spans[0].TotalFunctionCalls) -} - -// A request too short to have one nanosecond per segment used to divide by -// zero here. -func TestUnmarshal_VeryShortTrace(t *testing.T) { - assert.NotPanics(t, func() { - Unmarshal(trace.Trace{ - Metadata: trace.Metadata{StartTime: at(0), EndTime: at(5)}, - FunctionCalls: []trace.FunctionCall{call("a", 0, 5)}, - }, 50) - }) -} - -func TestUnmarshal_ZeroDurationTrace(t *testing.T) { - assert.NotPanics(t, func() { - Unmarshal(trace.Trace{ - Metadata: trace.Metadata{StartTime: at(100), EndTime: at(100)}, - FunctionCalls: []trace.FunctionCall{call("a", 100, 0)}, - }, 50) - }) -} diff --git a/pkg/trace/segmented/trace.go b/pkg/trace/segmented/trace.go index 23bc453..85ef50c 100644 --- a/pkg/trace/segmented/trace.go +++ b/pkg/trace/segmented/trace.go @@ -19,18 +19,15 @@ func Unmarshal(fullTrace trace.Trace, segments int64) Trace { // segment length of zero, and the bucketing below divides by it. segmentLength := max(fullTrace.Metadata.ExecutionTime()/time.Duration(segments), 1) - selfTimes := SelfTime(fullTrace.FunctionCalls) - spans := make(map[string]Span) - for i, call := range fullTrace.FunctionCalls { + for _, call := range fullTrace.FunctionCalls { span := Span{ Name: call.Name, Offset: call.Offset, Length: call.Elapsed, TotalFunctionCalls: 1, MaxMemory: call.Memory, - SelfTime: selfTimes[i], } var ( @@ -55,11 +52,6 @@ func Unmarshal(fullTrace trace.Trace, segments int64) Trace { span.MaxMemory = val.MaxMemory } - // Self time is the one field which accumulates rather than being - // taken from one of the merged calls: two calls of the same - // function each did their own work. - span.SelfTime += val.SelfTime - spans[key] = span continue } diff --git a/pkg/trace/segmented/trace_test.go b/pkg/trace/segmented/trace_test.go index 613cde9..e425412 100644 --- a/pkg/trace/segmented/trace_test.go +++ b/pkg/trace/segmented/trace_test.go @@ -186,3 +186,29 @@ func TestSpan_GetName_MultipleCalls(t *testing.T) { assert.Equal(t, "myFunc (3)", s.GetName()) } + +func TestSpan_DurationShare(t *testing.T) { + span := Span{Length: 250 * time.Nanosecond} + + assert.InDelta(t, 0.25, span.DurationShare(1000*time.Nanosecond), 0.001) + assert.Zero(t, span.DurationShare(0)) + assert.Zero(t, span.DurationShare(-time.Nanosecond)) +} + +// A request too short to have one nanosecond per segment must not divide by +// zero when calls are bucketed. +func TestUnmarshal_VeryShortTrace(t *testing.T) { + assert.NotPanics(t, func() { + Unmarshal(newTestTrace(0, 5, []trace.FunctionCall{ + {Name: "a", Offset: 0, Elapsed: 5}, + }), 50) + }) +} + +func TestUnmarshal_ZeroDurationTrace(t *testing.T) { + assert.NotPanics(t, func() { + Unmarshal(newTestTrace(100, 100, []trace.FunctionCall{ + {Name: "a", Offset: 100, Elapsed: 0}, + }), 50) + }) +} diff --git a/pkg/trace/segmented/types.go b/pkg/trace/segmented/types.go index a67ee10..d91a29e 100644 --- a/pkg/trace/segmented/types.go +++ b/pkg/trace/segmented/types.go @@ -32,18 +32,15 @@ type Span struct { TotalFunctionCalls int `json:"calls"` // MaxMemory used during this span. MaxMemory int64 `json:"maxMemory"` - // SelfTime is how long the calls in this span spent doing their own work, - // rather than waiting on the calls they made. See SelfTime. - SelfTime time.Duration `json:"selfTimeNanos"` } -// SelfShare of the request this span was itself responsible for. -func (s Span) SelfShare(executionTime time.Duration) float64 { - if executionTime <= 0 { +// DurationShare is the fraction of the request occupied by this span. +func (s Span) DurationShare(requestDuration time.Duration) float64 { + if requestDuration <= 0 { return 0 } - return float64(s.SelfTime) / float64(executionTime) + return float64(s.Length) / float64(requestDuration) } // GetName of the span and include the amount when more than one call.