Skip to content

N
nebula
Commit 6d48bac3 authored by protolambda's avatar protolambda Committed by GitHub
Browse files
Options

op-node: event tracers with diagram generation (#11101)

parent 01356153
Hide whitespace changes
Inline Side-by-side
Showing with 424 additions and 0 deletions
op-node/rollup/event/tracer_sequence.go 0 → 100644
View file @ 6d48bac3
package event
import (
"fmt"
"strings"
)
type SequenceTracer struct {
StructTracer
}
var _ Tracer = (*SequenceTracer)(nil)
func NewSequenceTracer() *SequenceTracer {
return &SequenceTracer{}
}
func (st *SequenceTracer) Output(showDurations bool) string {
st.l.Lock()
defer st.l.Unlock()
out := new(strings.Builder)
out.WriteString(`
<!DOCTYPE html>
<html lang="en">
<head>
<meta charset="utf-8">
<title>Sequence trace</title>
</head>
<body>
Sequence:
<pre class="mermaid">
`)
// Docs: https://mermaid.js.org/syntax/sequenceDiagram.html
_, _ = fmt.Fprintln(out, "sequenceDiagram")
// make sure the System is always the left-most entry in the diagram
_, _ = fmt.Fprintln(out, " participant System")
// other participants are implied by the following events
denyList := make(map[uint64]struct{})
for _, e := range st.Entries {
if e.Kind == TraceDeriveEnd && !e.DeriveEnd.Effect {
denyList[e.DerivContext] = struct{}{}
}
}
for _, e := range st.Entries {
// omit entries which just passed through but did not have any effective processing
if e.DerivContext != 0 {
if _, ok := denyList[e.DerivContext]; ok {
continue
}
}
switch e.Kind {
case TraceDeriveStart:
_, _ = fmt.Fprintf(out, " %%%% deriver-start %d\n", e.DerivContext)
_, _ = fmt.Fprintf(out, " System ->> %s: derive %s (%d)\n", e.Name, e.EventName, e.EmitContext)
_, _ = fmt.Fprintf(out, " activate %s\n", e.Name)
case TraceDeriveEnd:
_, _ = fmt.Fprintf(out, " deactivate %s\n", e.Name)
if showDurations {
_, _ = fmt.Fprintf(out, " Note over %s: duration: %s\n", e.Name, strings.ReplaceAll(e.DeriveEnd.Duration.String(), "µ", "#181;"))
}
_, _ = fmt.Fprintf(out, " %%%% deriver-end %d\n", e.DerivContext)
case TraceRateLimited:
_, _ = fmt.Fprintf(out, " Note over %s: rate-limited\n", e.Name)
case TraceEmit:
_, _ = fmt.Fprintf(out, " %%%% emit originates from %d\n", e.DerivContext)
_, _ = fmt.Fprintf(out, " %s -->> System: emit %s (%d)\n", e.Name, e.EventName, e.EmitContext)
_, _ = fmt.Fprintln(out, " activate System")
_, _ = fmt.Fprintln(out, " deactivate System")
}
}
out.WriteString(`
</pre>
<script src="https://cdn.jsdelivr.net/npm/mermaid@10.9.1/dist/mermaid.min.js"
integrity="sha384-WmdflGW9aGfoBdHc4rRyWzYuAjEmDwMdGdiPNacbwfGKxBW/SO6guzuQ76qjnSlr"
crossorigin="anonymous"></script>
<script>
mermaid.initialize({ startOnLoad: true, maxTextSize: 10000000 });
</script>
</body>
</html>
`)
return out.String()
}
op-node/rollup/event/tracer_struct.go 0 → 100644
View file @ 6d48bac3
package event
import (
"sync"
"time"
)
type TraceEntryKind int
const (
TraceDeriveStart TraceEntryKind = iota
TraceDeriveEnd
TraceRateLimited
TraceEmit
)
type TraceEntry struct {
Kind TraceEntryKind
Name string
DerivContext uint64
// Not present if Kind == TraceRateLimited
EmitContext uint64
// Not present if Kind == TraceRateLimited
EventName string
// Set to deriver start-time if derive-start/end, or emit-time if emitted. Not set if Kind == TraceRateLimited
EventTime time.Time
// Only present if Kind == TraceDeriveEnd
DeriveEnd struct {
Duration time.Duration
Effect bool
}
}
type StructTracer struct {
l sync.Mutex
Entries []TraceEntry
}
var _ Tracer = (*StructTracer)(nil)
func NewStructTracer() *StructTracer {
return &StructTracer{}
}
func (st *StructTracer) OnDeriveStart(name string, ev AnnotatedEvent, derivContext uint64, startTime time.Time) {
st.l.Lock()
defer st.l.Unlock()
st.Entries = append(st.Entries, TraceEntry{
Kind: TraceDeriveStart,
Name: name,
EventName: ev.Event.String(),
EmitContext: ev.EmitContext,
DerivContext: derivContext,
EventTime: startTime,
})
}
func (st *StructTracer) OnDeriveEnd(name string, ev AnnotatedEvent, derivContext uint64, startTime time.Time, duration time.Duration, effect bool) {
st.l.Lock()
defer st.l.Unlock()
st.Entries = append(st.Entries, TraceEntry{
Kind: TraceDeriveEnd,
Name: name,
EventName: ev.Event.String(),
EmitContext: ev.EmitContext,
DerivContext: derivContext,
EventTime: startTime,
DeriveEnd: struct {
Duration time.Duration
Effect bool
}{Duration: duration, Effect: effect},
})
}
func (st *StructTracer) OnRateLimited(name string, derivContext uint64) {
st.l.Lock()
defer st.l.Unlock()
st.Entries = append(st.Entries, TraceEntry{
Kind: TraceRateLimited,
Name: name,
DerivContext: derivContext,
})
}
func (st *StructTracer) OnEmit(name string, ev AnnotatedEvent, derivContext uint64, emitTime time.Time) {
st.l.Lock()
defer st.l.Unlock()
st.Entries = append(st.Entries, TraceEntry{
Kind: TraceEmit,
Name: name,
EventName: ev.Event.String(),
EmitContext: ev.EmitContext,
DerivContext: derivContext,
EventTime: emitTime,
})
}
op-node/rollup/event/tracer_timing.go 0 → 100644
View file @ 6d48bac3
package event
import (
"fmt"
"sort"
"strings"
"time"
"golang.org/x/exp/maps"
)
// TimingTracer generates an HTML output with an SVG that shows,
// per deriver, per event-type, bands for event-execution scaled by the execution time.
// This trace gives an idea of patterns between events and where execution-time is spent.
type TimingTracer struct {
StructTracer
}
var _ Tracer = (*TimingTracer)(nil)
func NewTimingTracer() *TimingTracer {
return &TimingTracer{}
}
func (st *TimingTracer) Output() string {
st.l.Lock()
defer st.l.Unlock()
out := new(strings.Builder)
out.WriteString(`
<!DOCTYPE html>
<html lang="en">
<head>
<meta charset="utf-8">
<title>Timing trace</title>
</head>
<body>
`)
var minTime, maxTime time.Time
denyList := make(map[uint64]struct{})
for _, e := range st.Entries {
if e.Kind == TraceDeriveEnd && !e.DeriveEnd.Effect {
denyList[e.DerivContext] = struct{}{}
}
if e.EventTime != (time.Time{}) && (minTime == (time.Time{}) || minTime.After(e.EventTime)) {
minTime = e.EventTime
}
if e.EventTime != (time.Time{}) && (maxTime == (time.Time{}) || e.EventTime.After(maxTime)) {
maxTime = e.EventTime
}
}
// Time spent on wallclock
realTime := maxTime.Sub(minTime)
// Accumulate entries grouped by actor, and then by event-name.
byActor := make(map[string]map[string][]TraceEntry)
rows := 0
for _, e := range st.Entries {
if e.Kind != TraceDeriveEnd && e.Kind != TraceEmit {
continue
}
// Omit entries which just passed through but did not have any effective processing
if e.DerivContext != 0 {
if _, ok := denyList[e.DerivContext]; ok {
continue
}
}
m, ok := byActor[e.Name]
if !ok {
m = make(map[string][]TraceEntry)
byActor[e.Name] = m
}
if len(m[e.EventName]) == 0 {
rows += 1
}
m[e.EventName] = append(m[e.EventName], e)
}
// for tick marks
rows += 2
// warning: viewbox resolution bounds: 24-bit max resolution, and 8-bit sub-pixel resolution
leftOffset := float64(300)
width := float64(2000)
incrementY := float64(10)
height := float64(rows) * incrementY
// min-x, min-y, width, and height
_, _ = fmt.Fprintf(out, `<svg viewBox="%f %f %f %f" preserveAspectRatio="none" width="2300" height="%d" style="border: 1px solid black">
`,
-leftOffset, 0.0, leftOffset+width, height, rows*10)
drawText := func(x, y float64, txt string) {
_, _ = fmt.Fprintf(out, `<text dy="1em" class="messageText"
style="font-size: 8px; font-weight: 300;"
x="%.3f" y="%.3f">%s</text>
`,
x, y, txt)
}
drawBox := func(x, y float64, w, h float64, strokeColor string, color string) {
strokeTxt := ""
if strokeColor != "" {
strokeTxt = `stroke="` + strokeColor + `" stroke-width="0.5px"`
}
_, _ = fmt.Fprintf(out, `<rect fill="%s" %s
x="%.3f" y="%.3f" width="%.3f" height="%.3f"></rect>
`, color, strokeTxt, x, y, w, h)
}
drawCircle := func(x, y float64, r float64, strokeColor string, color string) {
strokeTxt := ""
if strokeColor != "" {
strokeTxt = `stroke="` + strokeColor + `" stroke-width="0.5px"`
}
_, _ = fmt.Fprintf(out, `<circle fill="%s" %s
cx="%.3f" cy="%.3f" r="%.3f"></circle>
`, color, strokeTxt, x, y, r)
}
drawLine := func(x1, y1, x2, y2 float64, strokeWidth float64) {
_, _ = fmt.Fprintf(out, `<line stroke="#999" stroke-width="%.2fpx"
x1="%.3f" y1="%.3f" x2="%.3f" y2="%.3f"></line>
`, strokeWidth, x1, y1, x2, y2)
}
timeToX := func(v time.Time) float64 {
return width * float64(v.Sub(minTime)) / float64(realTime)
}
durationToX := func(v time.Duration) float64 {
return width * float64(v) / float64(realTime)
}
// sort the keys, to get deterministic diagram order
actors := maps.Keys(byActor)
sort.Strings(actors)
offsetY := float64(0)
textX := -leftOffset
derivCoords := make(map[uint64]struct{ x, y float64 })
emitCoords := make(map[uint64]struct{ x, y float64 })
row := 0
for _, actorName := range actors {
m := byActor[actorName]
derived := maps.Keys(m)
sort.Strings(derived)
for _, d := range derived {
if row%2 == 0 {
drawBox(-leftOffset/2, offsetY, width+leftOffset/2, incrementY, "", "#f4f4f4")
}
row += 1
drawLine(textX+leftOffset/2, offsetY, width, offsetY, 0.5)
drawText(textX+leftOffset/2, offsetY, d)
entries := m[d]
for _, e := range entries {
if e.Kind != TraceDeriveEnd && e.Kind != TraceEmit {
continue
}
x := timeToX(e.EventTime)
y := offsetY
if e.Kind == TraceDeriveEnd {
derivCoords[e.DerivContext] = struct{ x, y float64 }{x: x, y: y}
drawBox(x, y, durationToX(e.DeriveEnd.Duration), incrementY, "#aad", "#aad")
}
if e.Kind == TraceEmit {
emitCoords[e.EmitContext] = struct{ x, y float64 }{x: x, y: y}
// draw tiny point-centered circle to indicate event emission
r := incrementY / 4
drawCircle(x, y+(incrementY/2), r, "#daa", "#daa")
}
}
offsetY += incrementY
}
}
offsetY = float64(0)
for _, actorName := range actors {
subSectionH := incrementY * float64(len(byActor[actorName]))
drawText(textX+8.0, offsetY+subSectionH/2-incrementY/2, strings.ToUpper(actorName))
drawLine(textX, offsetY, width, offsetY, 2) // horizontal separator line to group actors
offsetY += subSectionH
}
drawLine(textX, offsetY, width, offsetY, 2) // horizontal separator line to group actors
// draw lines between event-emissions and event-execution
for _, actorName := range actors {
m := byActor[actorName]
derived := maps.Keys(m)
sort.Strings(derived)
for _, d := range derived {
entries := m[d]
for _, e := range entries {
if e.Kind == TraceDeriveEnd {
emitFrom, ok := emitCoords[e.EmitContext]
if !ok {
continue
}
derivTo := derivCoords[e.DerivContext]
drawLine(emitFrom.x, emitFrom.y+(incrementY/2), derivTo.x, derivTo.y+(incrementY/2), 0.5)
}
}
}
}
// draw tick marks
delta := realTime / 20
minDelta := time.Millisecond * 10
for {
if delta.Truncate(minDelta) == (delta + delta/3).Truncate(minDelta) {
delta = minDelta
break
} else {
minDelta *= 2
}
}
minTime = minTime.UTC()
// Round up to nearest multiple of delta (assuming delta < 1s)
start := delta - (time.Duration(minTime.Nanosecond()) % delta)
for x := start; x < realTime; {
posX := durationToX(x)
drawLine(posX, offsetY, posX, offsetY+incrementY/4, 2)
drawText(posX-incrementY, offsetY+incrementY/4, minTime.Add(x).Format("15:04:05.000"))
x += delta
}
// main label <> content separator line
drawLine(0, 0, 0, height, 1)
out.WriteString(`
</svg>
</body>
</html>
`)
return out.String()
}
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment