Add userland boot profiling to TSLOG

[cperciva]

Summary

Record, for each process ID:

• The timestamp of the fork() which creates it and the parent process ID,
• The path passed to execve(), if any,
• The first path resolved by namei, if any, and
• The timestamp of the exit() which terminates the process.

Allow this information to be dumped via a new sysctl, debug.tslog_user.

Note that recording namei is needed in order to obtain the names of rc.d scripts
being launched, as the rc system sources them in a subshell rather than execing
the scripts.

With this commit it is now possible to generate flamecharts of the entire boot
process from the start of the loader to the end of /etc/rc.

[cperciva]

Example flamechart:

tslog.svg132 KBDownload

[jlduran_gmail.com]

Nice!

Since you want to speed up primarily AWS instances, would disabling Duplicate Address Detection shave a couple of seconds of boot time (i.e. pass no_dad to ifconfig_DEFAULT in ec2.conf for testing purposes only)?

[mhorne]

Thanks, I love the simplicity of this.

I suppose you have some script to convert the output of debug.tslog_user to the flamegraph? It would be nice to have everything needed to generate these graphs checked in under tools/, in due time. The systctl output on its own doesn't look particularly human-readable.

A couple minor comments, but overall looks good to my eye.

sys/kern/kern_tslog.c

171

style(9) prefers explicit execname != NULL.

185

It is somewhat strange to have a function that performs four independent actions depending on the arguments provided, but I think its fine given the simplicity.

197

This check should be against pid_max, given that it is tunable with kern.pid_max.

200–201

Nit: %ju and uintmax_t are typically preferred for this type of thing.

[cperciva]

In D32493#733167, @jlduran_gmail.com wrote:

Nice!

Since you want to speed up primarily AWS instances, would disabling Duplicate Address Detection shave a couple of seconds of boot time (i.e. pass no_dad to ifconfig_DEFAULT in ec2.conf for testing purposes only)?

Looks like no_dad doesn't actually change how the rc.d scripts wait for things. But yes it looks like we're going to be making some DAD-related changes.

[cperciva]

In D32493#733398, @mhorne wrote:

I suppose you have some script to convert the output of debug.tslog_user to the flamegraph? It would be nice to have everything needed to generate these graphs checked in under tools/, in due time. The systctl output on its own doesn't look particularly human-readable.

Sorry, I should have mentioned it: https://github.com/cperciva/freebsd-boot-profiling

That github repo is where I've had the "process raw tslog data into a flamechart" code ever since I write tslog back in 2017.

[cperciva]

sys/kern/kern_tslog.c

171

Thanks, will fix.

185

Yeah I considered making it separate functions, but having a single interface had the advantage of simplifying the macro logic in sys/tslog.h which makes everything vanish when the kernel doesn't have options TSLOG.

197

Hmm, we have a static buffer, though -- static struct procdata { ... } procs[PID_MAX + 1]. I guess that could be allocated at runtime -- but since we probably only care about the first thousand-ish pids, it seems like unnecessary complication.

200–201

I'm using %lld for other 64-bit cycle counts in this file, so since this should work on all platforms I'd prefer to stay consistent.

[mhorne]

sys/kern/kern_tslog.c

197

I don't think the buffer needs to be allocated dynamically, since it is behind options TSLOG. I also doubt anyone would run tslog AND set the tunable, but in this odd case checking pid_max would avoid dumping the entries which are guaranteed to be empty. I'll leave it up to you.

200–201

Sounds good.