Profiling tools and initial optimizations

[zdykstra]

If other languages can do performance profiling, why can't bash ? Our debug log format already had the bulk of the information we need to generate per-function timing information.

run.sh -F or run.sh -E can now introduce a build-time variable, trace_term, which points to a serial device in the VM. On the host side, the serial port is attached to a FIFO which dumps data into a log file in the test environment directory. On the ZBM side, a debug trap points to the serial device. Every command executed in the interpreter causes the trap to fire, which dumps the current function stack and source (file) stack along with the current unix TS with nanosecond precision to the serial port.

Once the VM exits, a small perl tool re-assembles the trace/performance data to the format expected by Flamegraph. flamegraph.pl should be in $PATH on your local install. It'll generate ${FLAMECHART}/flamechart.svg and upload it if webify is on your system.

To protect against profiling code landing in a production release, a no-op /lib/profiling-lib.sh is installed by default that simply executes return 0 when sourced. The variable zfsbootmenu_enable_tracing must be enabled in a Dracut configuration file for the full-weight profiling library to be used.

Based on the flamechart generated, I've made the following changes:

• Omit network-legacy in the test environment, it spends a bunch of time messing with the KCL, etc
• Omit rootfs-block, dm, dmraid in the test environment - nothing we do needs what they provide and they're slow
• Add a dirty fast-fail to get_zbm_arg. When one lookup key is sent, use bashre to check if it's present in the KCL and return immediately if it's not.
• Remove zlog - preferring to directly echo to /dev/kmsg in anything but zdebug . zinfo has gone from ~24ms to 4ms.
• Move the getarg loglevel check to earlier in the KCL parsing, so we don't potentially miss zinfo logs (controlling terminal zinfo now works again!)
• Gate all zdebug calls in functions in the quick boot path with zdebug &&, avoiding building a string
• Replace a get_zbm_bool primary secondary call with two separate calls, to take advantage of fast fails
• Don't go into the countdown prompt if timeout=0 (zbm.skip).

Before: https://somebits.link/u/p/d62bdcd0da/stream
After: Flamegraph Flamechart

This is generally tested, but it could use a serious review of how the timing diff is generated and if it's valid. The downside to the profiler is that the trap, even as minimal as it is, adds a computation overhead. The timing values are consistent between runs, but they shouldn't be taken as absolute truth - they're inflated due to the time the trap takes to execute.

There are a number of Dracut optimizations that can probably still be done.

[ahesford]

Nice work, this will be nice to have in the test setup.

[ahesford]

Even without the profiling stuff, this refactors a lot of things quite nicely.