Rework SymbolizationComplete

[christos68k]

Summary

Updated SymbolizationComplete mechanism to reflect current semantics around trace processing and timestamping (no batching, in-kernel high resolution timestamps):

• Don't call SymbolizationComplete per-Trace, instead call it after each iteration of the perf event batch-drain loop. This introduces a call frequency upper bound (currently: 4Hz).
• Keep track of minimum KTime seen during trace event retrieval and report the minimum KTime belonging to the previous processing iteration with SymbolizationComplete.
• startPollingPerfEventMonitor is now specialized to trace event processing, this also simplifies caller logic.

TODO:

1. Generify SymbolizationComplete, fix Sending executable path for processes that have exited #278 Will open new PR for this.

Also see:

• Rework SymbolizationComplete mechanism #301

[christos68k]

Simplifying, SymbolizationComplete is now called from tracer/events.go with an introduced upper bound to the calling frequency.

[christos68k]

No point in having this be a generic function when:

1. Nothing else is currently using it (other than receiving trace events)
2. I'm introducing logic that's specialized to trace event handling

Instead, switching it to a Tracer method also simplifies the interface.

[christos68k]

This is how the logic looks now (polling loop and SymbolizationComplete being called).

On a system with low CPU load

WARN[0017] Poll events:0 oldKTime:0 minKTime:0          
WARN[0017] Poll events:0 oldKTime:0 minKTime:0          
WARN[0017] Poll events:1 oldKTime:0 minKTime:849288200358321 
WARN[0017] Poll events:0 oldKTime:849288200358321 minKTime:0 
WARN[0017] SymbolizationComplete captureKT: 849288200358321 latency: 288 ms 
WARN[0018] Poll events:0 oldKTime:0 minKTime:0          
WARN[0018] Poll events:4 oldKTime:0 minKTime:849288799647475 
WARN[0018] Poll events:1 oldKTime:849288799647475 minKTime:849289049572241 
WARN[0018] SymbolizationComplete captureKT: 849288799647475 latency: 438 ms 
WARN[0018] Poll events:0 oldKTime:849289049572241 minKTime:0 
WARN[0018] SymbolizationComplete captureKT: 849289049572241 latency: 438 ms 

We see 4 iterations of the polling loop per second (as expected due to 250ms polling interval) and SymbolizationComplete being called only when needed. The artificial latency in observed KTime remains below 500ms.

On a fully loaded system

WARN[0042] Poll events:30 oldKTime:849312250364163 minKTime:849312499384875 
WARN[0042] SymbolizationComplete captureKT: 849312250364163 latency: 496 ms 
WARN[0042] Poll events:38 oldKTime:849312499384875 minKTime:849312750439243 
WARN[0042] SymbolizationComplete captureKT: 849312499384875 latency: 500 ms 
WARN[0042] Poll events:49 oldKTime:849312750439243 minKTime:849313000197715 
WARN[0042] SymbolizationComplete captureKT: 849312750439243 latency: 501 ms 
WARN[0042] Poll events:46 oldKTime:849313000197715 minKTime:849313276705244 
WARN[0042] SymbolizationComplete captureKT: 849313000197715 latency: 506 ms 
WARN[0043] Poll events:54 oldKTime:849313276705244 minKTime:849313526712844 
WARN[0043] SymbolizationComplete captureKT: 849313276705244 latency: 483 ms 
WARN[0043] Poll events:19 oldKTime:849313526712844 minKTime:849313777505746 
WARN[0043] SymbolizationComplete captureKT: 849313526712844 latency: 468 ms 
WARN[0043] Poll events:59 oldKTime:849313777505746 minKTime:849314000068987 
WARN[0043] SymbolizationComplete captureKT: 849313777505746 latency: 480 ms 
WARN[0043] Poll events:46 oldKTime:849314000068987 minKTime:849314277230230 
WARN[0043] SymbolizationComplete captureKT: 849314000068987 latency: 506 ms 

Again we see 4 iterations of the polling loop per second, but this time SymbolizationComplete is being called at maximum frequency (4 times a second) as there are new trace events being received continuously. The artificial latency introduced is similar to the low CPU load case. Worst-case latency I've seen in a completely bogged down system is around 1000ms.

[rockdaboot]

Without a kt temp variable, the code is easier to read.

Suggested change

	kt := oldKTime
	if minKTime > 0 && minKTime < kt {
	// If current minKTime is smaller than oldKTime, use it
	// instead of oldKTime (and set it to 0 to avoid a repeat).
	kt = minKTime
	minKTime = 0
	}
	t.TraceProcessor().SymbolizationComplete(kt)
	if oldKTime <= minKTime {
	t.TraceProcessor().SymbolizationComplete(oldKTime)
	} else {
	// If minKTime is smaller than oldKTime, use it
	// and reset it to avoid a repeat.
	t.TraceProcessor().SymbolizationComplete(minKTime)
	minKTime = 0
	}

[christos68k]

Had to rework this a bit as the suggested logic was incorrect when minKTime == 0. See d12a80a.

[rockdaboot]

Now that you moved that code here it becomes obvious that we enforce a task/context switch for every trace. Possibly not for this PR, but we should improve this (e.g. with batch processing or a buffered channel).