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

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

From: Da Zheng <redacted>

From: Da Zheng <redacted>

We can record timing in the kernel by invoking bootstage_mark() or
bootstage_mark_early for early stages before memory and timekeeping
are initialized. It also uses debugfs to interact with the user space.

Signed-off-by: Da Zheng <redacted>
---
 include/linux/bootstage.h |   18 ++++
 include/linux/timer.h     |    3 +
 init/Kconfig              |    9 ++
 init/Makefile             |    1 +
 init/bootstage.c          |  228 +++++++++++++++++++++++++++++++++++++++++++++
 kernel/timer.c            |    9 ++
 6 files changed, 268 insertions(+), 0 deletions(-)
 create mode 100644 include/linux/bootstage.h
 create mode 100644 init/bootstage.c

diff --git a/include/linux/bootstage.h b/include/linux/bootstage.h
new file mode 100644
index 0000000..08df102
--- /dev/null
+++ b/include/linux/bootstage.h

@@ -0,0 +1,18 @@
+#ifndef __BOOTSTAGE_H
+#define __BOOTSTAGE_H
+
+#ifdef CONFIG_BOOTSTAGE
+unsigned long bootstage_mark(const char *name);
+unsigned long bootstage_mark_early(const char *name);
+#else
+static inline unsigned long bootstage_mark(const char *name)
+{
+	return 0;
+}
+static inline unsigned long bootstage_mark_early(const char *name)
+{
+	return 0;
+}
+#endif
+
+#endif

diff --git a/include/linux/timer.h b/include/linux/timer.h
index 6abd913..970e283 100644
--- a/include/linux/timer.h
+++ b/include/linux/timer.h

@@ -299,4 +299,7 @@ unsigned long __round_jiffies_up_relative(unsigned long j, int cpu);
 unsigned long round_jiffies_up(unsigned long j);
 unsigned long round_jiffies_up_relative(unsigned long j);
 
+/* Timer for bootstage, for now */
+unsigned long timer_get_us(void);
+
 #endif

diff --git a/init/Kconfig b/init/Kconfig
index d627783..f0f40ea 100644
--- a/init/Kconfig
+++ b/init/Kconfig

@@ -1399,3 +1399,12 @@ config PADATA
 	bool
 
 source "kernel/Kconfig.locks"
+
+config BOOTSTAGE
+	bool "Enable timing of boot stages"
+	help
+	  This enables to record the timing of different stages during boot.
+	  The timing in the kernel can be recorded by invoking bootstage_mark().
+	  The timing in the user space can be recorded by writing the stage name
+	  to /sys/kernel/debug/bootstage/mark. A report of information collected
+	  to date is available from /sys/kernel/debug/bootstage/report.

diff --git a/init/Makefile b/init/Makefile
index 0bf677a..7bfc047 100644
--- a/init/Makefile
+++ b/init/Makefile

@@ -8,6 +8,7 @@ obj-y                          += noinitramfs.o
 else
 obj-$(CONFIG_BLK_DEV_INITRD)   += initramfs.o
 endif
+obj-$(CONFIG_BOOTSTAGE)		+= bootstage.o
 obj-$(CONFIG_GENERIC_CALIBRATE_DELAY) += calibrate.o
 
 mounts-y			:= do_mounts.o

diff --git a/init/bootstage.c b/init/bootstage.c
new file mode 100644
index 0000000..79e9761
--- /dev/null
+++ b/init/bootstage.c

@@ -0,0 +1,228 @@
+#include <linux/debugfs.h>
+#include <linux/mutex.h>
+#include <linux/kernel.h>
+#include <linux/uaccess.h>
+#include <linux/slab.h>
+#include <linux/ktime.h>
+
+#include "linux/bootstage.h"
+
+#define BOOTSTAGE_COUNT 8
+#define MAX_NAME 32
+
+struct bootstage_record {
+	unsigned long time;
+	const char name[MAX_NAME];
+};
+
+static DEFINE_MUTEX(bootstage_mutex);
+
+/*
+ * this array is to record the bootstages at the beginning of
+ * kernel initialization, before memory is initialized.
+ */
+static struct bootstage_record bootstages[BOOTSTAGE_COUNT];
+
+/* the number of timing recorded in the bootstages array */
+static int num_bootstages;
+
+/* the space size of the bootstages array */
+static int cap_bootstages = BOOTSTAGE_COUNT;
+static struct bootstage_record *full_bootstages = bootstages;
+
+static unsigned long __bootstage_mark_early(int idx, const char *name)
+{
+	unsigned long curr = timer_get_us();
+
+	strlcpy(full_bootstages[idx].name, name, MAX_NAME);
+
+	/* this records timing in microseconds. */
+	full_bootstages[idx].time = curr;
+	return full_bootstages[idx].time;
+}
+
+static unsigned long __bootstage_mark(int idx, const char *name)
+{
+	struct timespec ts;
+
+	/* this function can be used only after timekeeping is called. */
+	ktime_get_ts(&ts);
+	strlcpy(full_bootstages[idx].name, name, MAX_NAME);
+
+	/* this records timing in microseconds. */
+	full_bootstages[idx].time = ts.tv_sec * 1000000 + ts.tv_nsec / 1000;
+	return full_bootstages[idx].time;
+}
+
+static inline int __inc_bootstages(void)
+{
+	struct bootstage_record *tmp;
+
+	cap_bootstages *= 2;
+	tmp = kmalloc(sizeof(*tmp) * cap_bootstages, GFP_KERNEL);
+	if (!tmp)
+		return -1;
+	memcpy(tmp, full_bootstages, sizeof(*tmp) * num_bootstages);
+
+	/*
+	 * full_bootstages first points to bootstages,
+	 * which is a static array.
+	 */
+	if (full_bootstages != bootstages)
+		kfree(full_bootstages);
+	full_bootstages = tmp;
+	return 0;
+}
+
+/*
+ * This is used during the initialization of the kernel.
+ */
+unsigned long bootstage_mark(const char *name)
+{
+	unsigned long ret;
+
+	mutex_lock(&bootstage_mutex);
+
+	if (num_bootstages == cap_bootstages) {
+		if (__inc_bootstages() < 0) {
+			mutex_unlock(&bootstage_mutex);
+			return -1;
+		}
+	}
+
+	ret = __bootstage_mark(num_bootstages, name);
+	num_bootstages++;
+
+	mutex_unlock(&bootstage_mutex);
+	return ret;
+}
+
+/*
+ * This is the same as bootstage_mark, but it can be used
+ * before memory and even timekeeping are initialized.
+ */
+unsigned long bootstage_mark_early(const char *name)
+{
+	unsigned long ret = 0;
+
+	mutex_lock(&bootstage_mutex);
+
+	if (num_bootstages < cap_bootstages) {
+		ret = __bootstage_mark_early(num_bootstages, name);
+		num_bootstages++;
+	}
+
+	mutex_unlock(&bootstage_mutex);
+	return ret;
+}
+
+static int get_bootstage_text(char *buf, int size)
+{
+	int i;
+	int written = 0;
+
+	for (i = 0; i < num_bootstages; i++) {
+		int ret = scnprintf(buf + written, size - written, "%s\t%ld\n",
+				full_bootstages[i].name,
+				full_bootstages[i].time);
+		written += ret;
+		if (written == size && i < num_bootstages - 1) {
+			printk(KERN_WARNING "bootstage: buffer exhausted");
+			break;
+		}
+	}
+	return written;
+}
+
+static ssize_t bootstage_read(struct file *file, char __user *buf,
+		size_t count, loff_t *ppos)
+{
+	int err = 0;
+	char *lbuf;
+	int written = 0;
+	int size = (MAX_NAME + 10) * num_bootstages;
+
+	/*
+	 * If the user tries to continue reading,
+	 * return 0 to notify the user all content has been read.
+	 */
+	if (*ppos)
+		return 0;
+
+	lbuf = kmalloc(size, GFP_KERNEL);
+	if (!lbuf)
+		return -ENOMEM;
+
+	mutex_lock(&bootstage_mutex);
+	err = -EFAULT;
+	written = get_bootstage_text(lbuf, size);
+	if (count > written)
+		count = written;
+	if (!copy_to_user(buf, lbuf, count)) {
+		err = count;
+		*ppos += count;
+	}
+
+	mutex_unlock(&bootstage_mutex);
+	kfree(lbuf);
+	return err;
+}
+
+static ssize_t bootstage_write(struct file *file, const char __user *buf,
+		size_t count, loff_t *ppos)
+{
+	char *lbuf;
+	int err = 0;
+
+	lbuf = kmalloc(count + 1, GFP_KERNEL);
+	if (!lbuf)
+		return -ENOMEM;
+	if (copy_from_user(lbuf, buf, count)) {
+		kfree(lbuf);
+		return -EFAULT;
+	}
+
+	/* The input string might end with \n or not end with null. */
+	if (lbuf[count - 1] == '\n')
+		lbuf[count - 1] = '\0';
+	else
+		lbuf[count] = '\0';
+
+	mutex_lock(&bootstage_mutex);
+	if (num_bootstages == cap_bootstages) {
+		if (__inc_bootstages() < 0)
+			err = -EFAULT;
+	}
+	if (err == 0) {
+		__bootstage_mark(num_bootstages, lbuf);
+		num_bootstages++;
+		err = count;
+	}
+	mutex_unlock(&bootstage_mutex);
+	kfree(lbuf);
+	return err;
+}
+
+static const struct file_operations report_operations = {
+	.read	= bootstage_read,
+};
+
+static const struct file_operations mark_operations = {
+	.write	= bootstage_write,
+};
+
+static int __init bootstage_init(void)
+{
+	struct dentry *dir;
+
+	dir = debugfs_create_dir("bootstage", NULL);
+	if (dir && !IS_ERR(dir)) {
+		debugfs_create_file("report", S_IFREG|S_IRUSR|S_IRGRP|S_IROTH,
+				dir, NULL, &report_operations);
+		debugfs_create_file("mark", S_IFREG|S_IWUSR,
+				dir, NULL, &mark_operations);
+	}
+	return 0;
+}
+
+postcore_initcall(bootstage_init);

diff --git a/kernel/timer.c b/kernel/timer.c
index 8cff361..cb49e0c 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c

@@ -1790,3 +1790,12 @@ void usleep_range(unsigned long min, unsigned long max)
 	do_usleep_range(min, max);
 }
 EXPORT_SYMBOL(usleep_range);
+
+/**
+ * A platform-specific timer to get the time since reset.
+ * It returns the time in microseconds.
+ */
+unsigned long __attribute__((weak)) timer_get_us(void)
+{
+	return 0;
+}

-- 
1.7.3.1

From: Da Zheng <redacted>

From: Da Zheng <redacted>

The bootstage driver accesses the u-boot timings in the device tree
and copies them to its array during initialization.

Signed-off-by: Da Zheng <redacted>
---
 arch/arm/kernel/time.c    |   29 +++++++++++++++++++++++++++++
 include/linux/bootstage.h |    1 +
 init/bootstage.c          |   36 ++++++++++++++++++++++++++++++++++++
 3 files changed, 66 insertions(+), 0 deletions(-)

diff --git a/arch/arm/kernel/time.c b/arch/arm/kernel/time.c
index cb634c3..524a1f5 100644
--- a/arch/arm/kernel/time.c
+++ b/arch/arm/kernel/time.c

@@ -24,6 +24,8 @@
 #include <linux/syscore_ops.h>
 #include <linux/timer.h>
 #include <linux/irq.h>
+#include <linux/bootstage.h>
+#include <linux/of.h>
 
 #include <linux/mc146818rtc.h>
 

@@ -156,3 +158,30 @@ void __init time_init(void)
 #endif
 }
 
+#ifdef CONFIG_BOOTSTAGE
+int get_prekernel_timing(void)
+{
+	struct device_node *node;
+	struct device_node *child;
+	int i = 0;
+
+	printk(KERN_INFO "TEST: bootstage_init is called in tegra\n");
+	node = of_find_node_by_path("/bootstage");
+	if (node == NULL)
+		return 0;
+
+	for_each_child_of_node(node, child) {
+		const char *name = of_get_property(child, "name", NULL);
+		const int *timep = of_get_property(child, "time", NULL);
+
+		if (name && timep) {
+			insert_bootstage(i, name,
+					(unsigned long) be32_to_cpu(*timep));
+			i++;
+		}
+	}
+	of_node_put(node);
+
+	return 0;
+}
+#endif

diff --git a/include/linux/bootstage.h b/include/linux/bootstage.h
index 08df102..95e837c 100644
--- a/include/linux/bootstage.h
+++ b/include/linux/bootstage.h

@@ -4,6 +4,7 @@
 #ifdef CONFIG_BOOTSTAGE
 unsigned long bootstage_mark(const char *name);
 unsigned long bootstage_mark_early(const char *name);
+void insert_bootstage(int idx, const char *name, unsigned long time);
 #else
 static inline unsigned long bootstage_mark(const char *name)
 {

diff --git a/init/bootstage.c b/init/bootstage.c
index 6f4668f..51f731d 100644
--- a/init/bootstage.c
+++ b/init/bootstage.c

@@ -75,6 +75,32 @@ static inline int __inc_bootstages(void)
 }
 
 /*
+ * Insert a new bootstage in the slot specified by `idx'.
+ * If the slot is already used, move it and slots behind it
+ * before inserting the new bootstage.
+ */
+void insert_bootstage(int idx, const char *name, unsigned long time)
+{
+	mutex_lock(&bootstage_mutex);
+
+	if (num_bootstages == cap_bootstages) {
+		if (__inc_bootstages() < 0) {
+			mutex_unlock(&bootstage_mutex);
+			return;
+		}
+	}
+
+	if (idx < num_bootstages)
+		memmove(&full_bootstages[idx + 1], &full_bootstages[idx],
+			sizeof(*full_bootstages) * (num_bootstages - idx));
+
+	strlcpy(full_bootstages[idx].name, name, MAX_NAME);
+	full_bootstages[idx].time = time;
+	num_bootstages++;
+	mutex_unlock(&bootstage_mutex);
+}
+
+/*
  * This is used during the initialization of the kernel.
  */
 unsigned long bootstage_mark(const char *name)

@@ -211,10 +237,20 @@ static const struct file_operations mark_operations = {
 	.write	= bootstage_write,
 };
 
+/*
+ * Get the timings that were recorded before the kernel is initialized.
+ */
+int __attribute__((weak)) get_prekernel_timing(void)
+{
+	return 0;
+}
+
 static int __init bootstage_init(void)
 {
 	struct dentry *dir;
 
+	get_prekernel_timing();
+
 	dir = debugfs_create_dir("bootstage", NULL);
 	if (dir && !IS_ERR(dir)) {
 		debugfs_create_file("report", S_IFREG|S_IRUSR|S_IRGRP|S_IROTH,

-- 
1.7.3.1

From: Da Zheng <redacted>

From: Da Zheng <redacted>

This inserts calls to bootstage_mark() to timestamp the kernel moving
between the different initcall levels.

Signed-off-by: Da Zheng <redacted>
---
 init/bootstage.c |   49 +++++++++++++++++++++++++++++++++++++++++++++++++
 init/main.c      |    7 +++++++
 2 files changed, 56 insertions(+), 0 deletions(-)

diff --git a/init/bootstage.c b/init/bootstage.c
index 79e9761..6f4668f 100644
--- a/init/bootstage.c
+++ b/init/bootstage.c

@@ -226,3 +226,52 @@ static int __init bootstage_init(void)
 }
 
 postcore_initcall(bootstage_init);
+
+static int __init post_core_initcall(void)
+{
+	bootstage_mark("core_initcall");
+	return 0;
+}
+core_initcall_sync(post_core_initcall);
+
+static int __init post_postcore_initcall(void)
+{
+	bootstage_mark("postcore_initcall");
+	return 0;
+}
+postcore_initcall_sync(post_postcore_initcall);
+
+static int __init post_arch_initcall(void)
+{
+	bootstage_mark("arch_initcall");
+	return 0;
+}
+arch_initcall_sync(post_arch_initcall);
+
+static int __init post_subsys_initcall(void)
+{
+	bootstage_mark("subsys_initcall");
+	return 0;
+}
+subsys_initcall_sync(post_subsys_initcall);
+
+static int __init post_fs_initcall(void)
+{
+	bootstage_mark("fs_initcall");
+	return 0;
+}
+fs_initcall_sync(post_fs_initcall);
+
+static int __init post_device_initcall(void)
+{
+	bootstage_mark("device_initcall");
+	return 0;
+}
+device_initcall_sync(post_device_initcall);
+
+static int __init post_late_initcall(void)
+{
+	bootstage_mark("late_initcall");
+	return 0;
+}
+late_initcall_sync(post_late_initcall);

diff --git a/init/main.c b/init/main.c
index 9c51ee7..671d6b7 100644
--- a/init/main.c
+++ b/init/main.c

@@ -75,6 +75,8 @@
 #include <asm/sections.h>
 #include <asm/cacheflush.h>
 
+#include <linux/bootstage.h>
+
 #ifdef CONFIG_X86_LOCAL_APIC
 #include <asm/smp.h>
 #endif

@@ -489,6 +491,7 @@ asmlinkage void __init start_kernel(void)
 	page_address_init();
 	printk(KERN_NOTICE "%s", linux_banner);
 	setup_arch(&command_line);
+	bootstage_mark_early("bootstage_start");
 	mm_init_owner(&init_mm, &init_task);
 	mm_init_cpumask(&init_mm);
 	setup_command_line(command_line);

@@ -627,6 +630,7 @@ asmlinkage void __init start_kernel(void)
 	sfi_init_late();
 
 	ftrace_init();
+	bootstage_mark("before_rest_init");
 
 	/* Do the rest non-__init'ed, we're now alive */
 	rest_init();

@@ -722,6 +726,7 @@ static void __init do_basic_setup(void)
 	driver_init();
 	init_irq_proc();
 	do_ctors();
+	bootstage_mark("before_initcalls");
 	do_initcalls();
 }
 

@@ -806,6 +811,7 @@ static int __init kernel_init(void * unused)
 	sched_init_smp();
 
 	do_basic_setup();
+	bootstage_mark("after_basic_setup");
 
 	/* Open the /dev/console on the rootfs, this should never fail */
 	if (sys_open((const char __user *) "/dev/console", O_RDWR, 0) < 0)

@@ -832,6 +838,7 @@ static int __init kernel_init(void * unused)
 	 * initmem segments and start the user-mode stuff..
 	 */
 
+	bootstage_mark("before_init_post");
 	init_post();
 	return 0;
 }

-- 
1.7.3.1

On Fri, Sep 23, 2011 at 5:03 PM, Simon Glass [off-list ref] wrote:

I'm sure you considered just instrumenting do_one_initcall() rather
than adding these individual initcall marks?  That would get you a lot
more timestamps (maybe too many), and would help identify individual
drivers, which I suspect will be common offenders.

Bjorn

On Fri, Sep 23, 2011 at 04:03:15PM -0700, Simon Glass wrote:

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.

Not another 'get a time value' function.  Why do we need soo many?
We have - at least:

ktime_get (and various flavours of it)
do_gettimeofday
getnstimeofday
sched_clock

Do we really need yet another one which will have to be multiplexed
amongst platforms, requiring scaling and so forth from whatever the
platform provides?

Remember that ARM timers are virtually all MMIO mapped, which means
they don't work during early kernel bringup when the MMU mappings for
the hardware have not been setup.  (That's the reason stuff like
sched_clock for printk doesn't work early.)  That can't be solved by
creating yet another per-platform method to get microseconds.

Hi Russell,

On Sat, Sep 24, 2011 at 1:32 AM, Russell King - ARM Linux
[off-list ref] wrote:

On Fri, Sep 23, 2011 at 04:03:15PM -0700, Simon Glass wrote:

quoted

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.

Not another 'get a time value' function. ?Why do we need soo many?
We have - at least:

ktime_get (and various flavours of it)
do_gettimeofday
getnstimeofday
sched_clock

Do we really need yet another one which will have to be multiplexed
amongst platforms, requiring scaling and so forth from whatever the
platform provides?

No we don't need another! It is just a convenience for this RFC since
the actual timer mechanism is not clear and not important for this
RFC. Insert your favourite timer mechanism instead.

Remember that ARM timers are virtually all MMIO mapped, which means
they don't work during early kernel bringup when the MMU mappings for
the hardware have not been setup. ?(That's the reason stuff like
sched_clock for printk doesn't work early.) ?That can't be solved by
creating yet another per-platform method to get microseconds.

While it would be useful to measure early things like kernel
decompression, it's hard to make that work cross-platform and there
are other problems like you raise, and where to store timing info.

Hi,

Russell King - ARM Linux a ?crit :

On Fri, Sep 23, 2011 at 04:03:15PM -0700, Simon Glass wrote:

quoted

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.

Not another 'get a time value' function.  Why do we need soo many?
We have - at least:

ktime_get (and various flavours of it)
do_gettimeofday
getnstimeofday
sched_clock

Do we really need yet another one which will have to be multiplexed
amongst platforms, requiring scaling and so forth from whatever the
platform provides?

Remember that ARM timers are virtually all MMIO mapped, which means
they don't work during early kernel bringup when the MMU mappings for
the hardware have not been setup.  (That's the reason stuff like
sched_clock for printk doesn't work early.)

Doesn't cortexA-8 (and A9 ?) have a cycle counter that can be read by
coprocessor 15 ?

Couldn't we use that counter for early stuff on those architectures ?


Matthieu

Hi Matthieu,

On Mon, Sep 26, 2011 at 12:53 AM, Matthieu CASTET
[off-list ref] wrote:

Hi,

Russell King - ARM Linux a ?crit :

quoted

On Fri, Sep 23, 2011 at 04:03:15PM -0700, Simon Glass wrote:

quoted

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.

Not another 'get a time value' function. ?Why do we need soo many?
We have - at least:

ktime_get (and various flavours of it)
do_gettimeofday
getnstimeofday
sched_clock

Do we really need yet another one which will have to be multiplexed
amongst platforms, requiring scaling and so forth from whatever the
platform provides?

Remember that ARM timers are virtually all MMIO mapped, which means
they don't work during early kernel bringup when the MMU mappings for
the hardware have not been setup. ?(That's the reason stuff like
sched_clock for printk doesn't work early.)

Doesn't cortexA-8 (and A9 ?) have a cycle counter that can be read by
coprocessor 15 ?

Couldn't we use that counter for early stuff on those architectures ?

Yes we could, but we need to be careful that we use a 'time of day'
counter, not dependent on clock speed, CPU load and the like. See my
other email for what I see as the ideal timer. Obviously this will
have to be architecture-specific, but I hope for a simple fallback to
something available on all architectures, with perhaps the ability to
use better timers available on specific architectures which implement
them.

Regards,
Simon

Matthieu

On Fri, Sep 23, 2011 at 5:03 PM, Simon Glass [off-list ref] wrote:

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.

I think this is a cool idea.  It's quite difficult to extract this
sort of information today, and making it easily and consistently
available should help focus attention and improve things.

There are difficult issues about which clock to use, how to correlate
bootloader & kernel timestamps, how to make sure the timestamps stay
sensible even when we use hwclock, ntp, etc., but I think it's worth
pushing on this to see how far you can go.

Bjorn

Hi Bjorn,

On Sun, Sep 25, 2011 at 5:54 AM, Bjorn Helgaas [off-list ref] wrote:

On Fri, Sep 23, 2011 at 5:03 PM, Simon Glass [off-list ref] wrote:

quoted

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.

I think this is a cool idea. ?It's quite difficult to extract this
sort of information today, and making it easily and consistently
available should help focus attention and improve things.

There are difficult issues about which clock to use, how to correlate
bootloader & kernel timestamps, how to make sure the timestamps stay
sensible even when we use hwclock, ntp, etc., but I think it's worth
pushing on this to see how far you can go.

Yes it is not easy to get all of this right, especially trying to
cross two completely different projects. I think the timestamps should
be measured from reset. The kernel timestamps start not at zero, but
from the time the kernel starts. This guarantees a consistent time
base across the data. Also if there is a pre-boot program (such as a
NAND loader) then its time will be counted also.

A good timer would be an accurate monotonic wall clock, not
necessarily related to time of day. An ideal timer would be a
microsecond/nanosecond timer maintained by the hardware / SOC.

Regards,
Simon

Bjorn

On 09/23/2011 04:03 PM, Simon Glass wrote:

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.

I would be very interested in this.  This is something that
would be very helpful, I believe, to assist with optimizing
overall boot time.

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.

'cat /proc/uptime >/dev/kmsg' (with printk timestamps on) is much
better than the above, for this reason.

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

...

I would prefer the timestamp in the first column.  Also, for consistency
it would be good if it used the same format as printk timestamps:
"[%5lu.%06lu]" with seconds and micro-seconds in the respective fields.
Then, existing tools like scripts/show_delta and scripts/bootgraph.pl
could work on this data as well.

Full micro-second granularity is not required, but it's nice to keep
the format the same, whether the clock supports it or not.

Finally, is this work related at all to this:
http://lists.denx.de/pipermail/u-boot/2011-September/099996.html
Bootgraph.pl instrumentation support for UBoot
??

Just wondering.

Thanks - this looks like great stuff!
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Workgroup of the Linux Foundation
Senior Staff Engineer, Sony Network Entertainment
=============================

Sorry for the dup.  Mailer freaking out.
My apologies...
 -- Tim

Hi Tim,

On Tue, Sep 27, 2011 at 10:56 AM, Tim Bird [off-list ref] wrote:

On 09/23/2011 04:03 PM, Simon Glass wrote:

quoted

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.

I would be very interested in this. ?This is something that
would be very helpful, I believe, to assist with optimizing
overall boot time.

Good.

quoted

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.

'cat /proc/uptime >/dev/kmsg' (with printk timestamps on) is much
better than the above, for this reason.

Yes, although this needs root access on my machine. Am hoping to have
something easily accessible from user space.

quoted

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

...

I would prefer the timestamp in the first column. ?Also, for consistency
it would be good if it used the same format as printk timestamps:
"[%5lu.%06lu]" with seconds and micro-seconds in the respective fields.
Then, existing tools like scripts/show_delta and scripts/bootgraph.pl
could work on this data as well.

Yes that makes sense, I will adjust it.

Full micro-second granularity is not required, but it's nice to keep
the format the same, whether the clock supports it or not.

Yes, and it's surprising how often microsecond accuracy is useful. For
example, recently I was looking at the impact of reduced
voltage/frequency early in boot on an ARM platform. The difference was
only a few ms, and the microsecond timer resolution helped a lot in
seeing the impact of these changes.

Finally, is this work related at all to this:
http://lists.denx.de/pipermail/u-boot/2011-September/099996.html
Bootgraph.pl instrumentation support for UBoot
??

Just wondering.

It is related in the sense that ideally all of this would come
together and play nicely. That's an interesting patch also, and there
are a few threads to tie together in U-Boot independently of the
kernel.

My original U-Boot patch set was here:

http://lists.denx.de/pipermail/u-boot/2011-May/092584.html

Thanks - this looks like great stuff!

Thanks!

Regards,
Simon

?-- Tim

=============================
Tim Bird
Architecture Group Chair, CE Workgroup of the Linux Foundation
Senior Staff Engineer, Sony Network Entertainment
=============================