Late traces

[eugeneia]

This issue serves to document my brief investigation of JIT activity late into lwaftr data plane process execution. Below are screenshots from a Studio session showing JIT activity ~50 minutes after the process started handling packets.

Notably, lib.ptree.alarms seems to be responsible for many late traces (or attempts thereof). However there are also things happening like core.lib.compiler_barrier being trace compiled after ~30 minutes. At a first glance most of the traces seem legitimate to me, i.e. they are cases where some common but rare code paths are traced when they hit a certain warmness.

Random brain fluke: I wonder, if this sort of late trace activity is undesired, if we could add periodic hot counter clearing to raptorjit? As in, clear the hot counters every second so that they don’t accumulate over long periods of time, and “lingering” code doesn’t cause JIT activity (if it is indeed the case that this is what is happening here.)

[lukego]

I wonder, if this sort of late trace activity is undesired, if we could add periodic hot counter clearing to raptorjit?

I like this idea a lot. Code gets hot when you hit it frequently and frequency is about both number of hits and length of time. There's a big difference between a function that's called a thousand times over one second verses a thousand times over one hour or one day or one week.

[eugeneia]

Yeah, I called it brain fluke because I did not actually look into whether RaptorJIT makes any relation between the real world time and its measure of frequency/hotness already. But my thoughts exactly. :-)

[eugeneia]

I’ve implemented this idea in https://github.com/raptorjit/raptorjit/pull/260 and tested it with lwaftr-next. The results show some promise at least. Latest JIT activity seems to be ~5 minutes after load starts (vs the previous ~1 hour):

We could merge this onto the lwaftr branch for some relief if we decide that the late traces activity are a problem for us (more testing needed I guess).

[wingo]

Very interesting idea!

I suppose that before we had so many things running on timers, they ran periodically via app push functions, so the JIT would explore all runnable code relatively early in the life of an application, and JIT activity would stop. But with timers it is taking longer for the JIT to explore interpreted traces. Also there's more code than there used to be. Could it be that a there is a percentage of code running interpreted that's OK? Right now the counter mechanism would tend to drive interpreted code to zero percent over time, but I don't know if setting a floor might be useful... In any case a good tool to throw at a problem, when and if we actually do see a problem.

[wingo]

Just to round out the discussion here -- for the 2019.06.02 lwAFTR release we incorporated these changes and they made a big difference to long-term stability. The commits are all on https://github.com/eugeneia/snabb/commits/stable-perf. From https://github.com/Igalia/snabb/blob/lwaftr/src/program/lwaftr/doc/CHANGELOG.md#20190602:

Snabb uses LuaJIT, which is a just-in-time compiler. LuaJIT compiles program segments called traces. Traces can jump to each other, and thereby form a graph. The shape of the trace graph can have important performance impacts on a network function, but building the optimal graph shape is fundamentally hard. Usually LuaJIT does a good job, but if a network function is dropping packets, Snabb's "ingress drop monitor" will ask LuaJIT to re-learn the graph of traces, in the hopes that this self-healing process will fix the packet loss situation.

Unfortunately, the self-healing process has some poor interactions with so-called "long tail" traces -- traces that aren't taking an important amount of time, but which LuaJIT might decide to compile a few seconds into the running of a network function. Compiling a trace can cause a latency spike and dropped packets, so the work of compiling these long-tail traces can in fact be interpreted as a packet loss situation, thereby triggering the self-healing process, leading to a pathologically repeating large packet loss situation.

The right answer is for LuaJIT to avoid the latency cost for long-tail trace compilation. While this might make long-tail traces run not as fast as they would if they were compiled, these traces take so little time anyway that it doesn't matter enough to pay the cost of trace compilation.

[wingo]

Also note that we added a patch by @eugeneia to also zero out side exit counters, in addition to the hotloop counters. It's in stable-perf.

[eugeneia]

Yup, that patch is also in https://github.com/raptorjit/raptorjit/pull/260 :+1: