[RFC PATCH 0/3] Add accurate boot timing to a Linux system

[Simon Glass]

This experimental patch set adds boot timing to a Linux system. The
timing starts with the boot loader and extends through the kernel into
user space to the completion of the boot process. The timing starts when
the system leaves reset, not later when the kernel starts.

The concept is:
- Boot loader records a timestamp for key events during its operation
- These timestamps are passed to Linux, which adds more as it boots
- These timestamps are made available to user space, where more
timestamps are added as init does its job
- Finally the whole record is collected by a user-space script run at
the end of init. This is fed back through some mechanism to monitor
boot time in the field.

The bootstage record aims to provide 20-30 timestamps ranging from reset
to login prompt (or some other definition of completion).

Current kernel timing architecture
----------------------------------
This is a note on what is currently in the kernel and what may justify
adding something new.

At present kernel support for boot timing does not extend to before
Linux was loaded. This means that boot-time regressions in the boot
loader are silently missed. Even it is possible to determine how long
the boot loader took to run without being told, this information will
lack any detail, such as how much time was taken initializing devices,
how much time to load the kernel, etc.

Within the kernel, timing information is typically written with each
printk() (for example dmesg has timing in brackets at the start of each
line). This log information can be analyzed later to look for particular
messages which are known to be printed at different stages of the
kernel boot. However, this approach is fragile, since the messages can
change or disappear altogether, and the code is in two places: kernel
creates the messages and user space tools look for them. Also there are
few such messages and the init order is not guaranteed and can change
from kernel release to release, and from one hardware platform to
another.

When the kernel boots it is difficult to obtain early boot timing.
Existing tracing tools are inited after the architecture code and not
early enough to provide full coverage of the kernel boot process.

Individual developers who are interested in boot time can instrument
their kernel with new messages, and write tools to look for them. But
these messages must be maintained in their local source tree and bloat
the logs. When a device goes into production such changes are generally
left out of the 'production build' with the result that accurate boot
timing is not done in the field even if a mechanism is made available to
report back other information.

Finally, in user space there is no kernel-blessed way to record
timestamps. One approach is to add lines to the init scripts like
'cat /proc/uptime >/tmp/login_starts'. This creates another place where
the boot timing tool must look for information.

This Patchset
-------------
This patchset aims to unify timing in one place: a simple driver which
collects pre-kernel boot timestamps, adds its own as it boots, with
calls to bootstage_mark(), then allows user space (init, etc.) to add
more with 'echo "message" >>/sys/kernel/debug/bootstage/mask'.

Finally it permits user space to access the full list of timestamps
with 'cat /sys/kernel/debug/bootstage/report', which has two columns:
the stage name and the timestamp:

	reset	0
	arch_cpu_init-AVP	258902
	arch_cpu_init-A9	263267
	arch_cpu_init-done	263312
	board_init_f-start	263314
	board_init_r-start	323671
	main_loop	573008
	usb_start	610771
	bootm_start	11685215
	start_kernel	11899970
	bootstage_start	12278316
	before_rest_init	12563688
	before_initcalls	12855611
	core_initcall	12856077
	postcore_initcall	12856742
	arch_initcall	12859536
	subsys_initcall	12927416
	fs_initcall	12944422
	device_initcall	16765564
	late_initcall	16858665
	after_basic_setup	16858673
	before_init_post	18368183
	pre-startup	21956927
	post-startup	23657468
	x-started	30091946
	chrome-exec	30511367
	login-prompt-ready	41864650
	login-prompt-visible	43850932
	boot-complete	44014786

Transfer of information from the boot loader to the kernel is just a
prototype at present. This patch set uses the device tree and works on
hardware which uses a device tree (e.g. ARM). Patches are in progress
for one boot loader (U-Boot, commonly used on ARM systems) to support
the other side of this.

An accurate timer is required to make the numbers meaningful. Many
modern platforms have a microsecond timer. This patch set uses a
function called timer_get_us() to read the timer. The implementation of
that is not included in this RFC patch set.

Also not included in this patch set is an ID number for each stage. We
have gone with a simple string since it is easier to extend and modify
across software boundaries. But the intention is that these strings (at
least within the kernel) remain unchanged over time, barring a
significant refactor of the code which emits them.

Comments
--------
At this early stage (and more spending too much time polishing) I am looking
for comments:

1. How does this approach compare with other (existing) ways of doing
this?

2. Does anyone have existing patches / ideas in this area?

3. What standard way is there of passing boot timing from a boot load to
the kernel (other than the fdt as used here)?


Da Zheng (3):
  bootstage: Add bootstages to record timing in the kernel.
  bootstage: Insert bootstage_mark to record timing for bootup.
  bootstage: Get u-boot timing from the device tree.

 arch/arm/kernel/time.c    |   29 ++++
 include/linux/bootstage.h |   19 +++
 include/linux/timer.h     |    3 +
 init/Kconfig              |    9 ++
 init/Makefile             |    1 +
 init/bootstage.c          |  313 +++++++++++++++++++++++++++++++++++++++++++++
 init/main.c               |    7 +
 kernel/timer.c            |    9 ++
 8 files changed, 390 insertions(+), 0 deletions(-)
 create mode 100644 include/linux/bootstage.h
 create mode 100644 init/bootstage.c

-- 
1.7.3.1