Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 15 additions & 17 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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.

Expand Down
19 changes: 5 additions & 14 deletions pkg/app/component/span/span.go
Original file line number Diff line number Diff line change
@@ -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 (
Expand Down Expand Up @@ -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.
Expand All @@ -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
}

Expand Down Expand Up @@ -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),
}
}

Expand Down Expand Up @@ -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
)

Expand Down
20 changes: 10 additions & 10 deletions pkg/app/component/span/span_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
31 changes: 8 additions & 23 deletions pkg/app/functions.go
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,7 @@ import (

// Widths of the functions columns.
const (
functionsWidthSelf = 6
functionsWidthShare = 6
functionsWidthMemory = 10
functionsWidthTimeline = 44
functionsWidthElapsed = 8
Expand All @@ -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},
Expand Down Expand Up @@ -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),
Expand All @@ -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),
})
Expand Down Expand Up @@ -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",
Expand All @@ -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
}
8 changes: 3 additions & 5 deletions pkg/app/help.go
Original file line number Diff line number Diff line change
Expand Up @@ -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."},
},
},
}
Expand Down
9 changes: 2 additions & 7 deletions pkg/app/search.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
4 changes: 2 additions & 2 deletions pkg/app/theme/palette_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand Down
10 changes: 3 additions & 7 deletions pkg/app/theme/severity.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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:
Expand Down
Loading
Loading