diff mbox

Boottime: A tool for automatic measurement of kernel/bootloader boot time

Message ID 20121012164221.GN12567@gmail.com
State New
Headers show

Commit Message

Lee Jones Oct. 12, 2012, 4:42 p.m. UTC 
On Fri, 12 Oct 2012, Dan Murphy wrote:

> 
> On 10/12/2012 09:01 AM, Lee Jones wrote:
> >On Fri, 12 Oct 2012, Arnd Bergmann wrote:
> >
> >>On Friday 12 October 2012, Russell King - ARM Linux wrote:
> >>>>root@ME:/ cat /sys/kernel/debug/boottime/bootgraph
> >>>>[    0.185254] calling  splash+0x0/0x0
> >>>>[    2.984335] initcall splash+0x0/0x0 returned 0 after 2799 msecs.
> >>>>[    2.984335] calling  autoboot_delay+0x0/0x0
> >>>>[    4.089513] initcall autoboot_delay+0x0/0x0 returned 0 after 1105 msecs.
> >>>>[    4.089513] calling  load_kernel+0x0/0x0
> >>>>[    4.239174] initcall load_kernel+0x0/0x0 returned 0 after 149 msecs.
> >>>>[    4.239174] calling  boot_kernel+0x0/0x0
> >>>>[    4.276260] initcall boot_kernel+0x0/0x0 returned 0 after 37 msecs.
> >>>>[    4.276260] calling  uncompress_ll_init+0x0/0x0
> >>>>[    4.276260] initcall uncompress_ll_init+0x0/0x0 returned 0 after 0 msecs.
> >>>>[    4.276260] Freeing init memory: 0K
> >>>Umm, what happened to sysfs not becoming procfs v2?  I thought we had
> >>>a fairly strict requirement for "one value per file and not nicely
> >>>formatted" for sysfs?
> >>>
> >>I was thinking the same thing at first, but then I noticed it's actually
> >>debugfs, which has no such rules.
> >Right. :)
> >
> OK I don't see when boottime_activate is called.
> 
> Where would this call actually be made from?
> 
> I see the call to deactivate but no call to activate.

Here perhaps (Jonas, alerted me to the missing patch):

commit 4c49a18bcfd2d041cbad7f41c6e6b39d90008382 (HEAD, refs/heads/dt-snowball-pre-rc1)
Author: Jonas Aaberg <jonas.aberg@stericsson.com>
Date:   Wed Sep 14 09:29:20 2011 +0200

    drivers: clocksource: dbx500-prcmu: Add boottime support
    
    Change-Id: I9b5e3d050131c08c08786ae84cb76619c0525049
    Signed-off-by: Jonas Aaberg <jonas.aberg@stericsson.com>
    Reviewed-on: http://gerrit.lud.stericsson.com/gerrit/32055

Comments

Dan Murphy Oct. 15, 2012, 3:52 p.m. UTC | #1 
On 10/12/2012 11:42 AM, Lee Jones wrote:
> On Fri, 12 Oct 2012, Dan Murphy wrote:
>
>> On 10/12/2012 09:01 AM, Lee Jones wrote:
>>> On Fri, 12 Oct 2012, Arnd Bergmann wrote:
>>>
>>>> On Friday 12 October 2012, Russell King - ARM Linux wrote:
>>>>>> root@ME:/ cat /sys/kernel/debug/boottime/bootgraph
>>>>>> [    0.185254] calling  splash+0x0/0x0
>>>>>> [    2.984335] initcall splash+0x0/0x0 returned 0 after 2799 msecs.
>>>>>> [    2.984335] calling  autoboot_delay+0x0/0x0
>>>>>> [    4.089513] initcall autoboot_delay+0x0/0x0 returned 0 after 1105 msecs.
>>>>>> [    4.089513] calling  load_kernel+0x0/0x0
>>>>>> [    4.239174] initcall load_kernel+0x0/0x0 returned 0 after 149 msecs.
>>>>>> [    4.239174] calling  boot_kernel+0x0/0x0
>>>>>> [    4.276260] initcall boot_kernel+0x0/0x0 returned 0 after 37 msecs.
>>>>>> [    4.276260] calling  uncompress_ll_init+0x0/0x0
>>>>>> [    4.276260] initcall uncompress_ll_init+0x0/0x0 returned 0 after 0 msecs.
>>>>>> [    4.276260] Freeing init memory: 0K
>>>>> Umm, what happened to sysfs not becoming procfs v2?  I thought we had
>>>>> a fairly strict requirement for "one value per file and not nicely
>>>>> formatted" for sysfs?
>>>>>
>>>> I was thinking the same thing at first, but then I noticed it's actually
>>>> debugfs, which has no such rules.
>>> Right. :)
>>>
>> OK I don't see when boottime_activate is called.
>>
>> Where would this call actually be made from?
>>
>> I see the call to deactivate but no call to activate.
> Here perhaps (Jonas, alerted me to the missing patch):
>
> commit 4c49a18bcfd2d041cbad7f41c6e6b39d90008382 (HEAD, refs/heads/dt-snowball-pre-rc1)
> Author: Jonas Aaberg<jonas.aberg@stericsson.com>
> Date:   Wed Sep 14 09:29:20 2011 +0200
>
>      drivers: clocksource: dbx500-prcmu: Add boottime support
>
>      Change-Id: I9b5e3d050131c08c08786ae84cb76619c0525049
>      Signed-off-by: Jonas Aaberg<jonas.aberg@stericsson.com>
>      Reviewed-on: http://gerrit.lud.stericsson.com/gerrit/32055
>
> diff --git a/drivers/clocksource/clksrc-dbx500-prcmu.c b/drivers/clocksource/clksrc-dbx500-prcmu.c
> index c26c369..0069cd9 100644
> --- a/drivers/clocksource/clksrc-dbx500-prcmu.c
> +++ b/drivers/clocksource/clksrc-dbx500-prcmu.c
> @@ -14,6 +14,7 @@
>    */
>   #include<linux/clockchips.h>
>   #include<linux/clksrc-dbx500-prcmu.h>
> +#include<linux/boottime.h>
>
>   #include<asm/sched_clock.h>
>
> @@ -68,6 +69,23 @@ static u32 notrace dbx500_prcmu_sched_clock_read(void)
>
>   #endif
>
> +#ifdef CONFIG_BOOTTIME
> +static unsigned long __init boottime_get_time(void)
> +{
> +	return div_s64(clocksource_cyc2ns(clocksource_dbx500_prcmu.read(
> +						&clocksource_dbx500_prcmu),
> +					  clocksource_dbx500_prcmu.mult,
> +					  clocksource_dbx500_prcmu.shift),
> +		       1000);
> +}
> +
> +static struct boottime_timer __initdata boottime_timer = {
> +	.init     = NULL,
> +	.get_time = boottime_get_time,
> +	.finalize = NULL,
> +};
> +#endif
> +
>   void __init clksrc_dbx500_prcmu_init(void __iomem *base)
>   {
>   	clksrc_dbx500_timer_base = base;
> @@ -90,4 +108,6 @@ void __init clksrc_dbx500_prcmu_init(void __iomem *base)
>   			 32, RATE_32K);
>   #endif
>   	clocksource_register_hz(&clocksource_dbx500_prcmu, RATE_32K);
> +
> +	boottime_activate(&boottime_timer);
>   }
>

OK So has this been validated and tested on any other IC then a ST part?
This boottime_activate patch seems to be only for the dbx500.  If this 
is supposed to be a generic solution I would expect
a generic patch for ARM to enable boot time activation.

Have you profiled how much time the boot time logging has added to the 
over all boot?
Also the boottime commit message should explain a little more what it is 
measuring.
i.e.  This patch enables logging the boot time from point x to point y 
for the kernel only.  This does not include init.

What about adding the boot time from the init sequence to init complete?
Lee Jones Oct. 16, 2012, 7:34 a.m. UTC | #2 
> >>>>>>root@ME:/ cat /sys/kernel/debug/boottime/bootgraph
> >>>>>>[    0.185254] calling  splash+0x0/0x0
> >>>>>>[    2.984335] initcall splash+0x0/0x0 returned 0 after 2799 msecs.
> >>>>>>[    2.984335] calling  autoboot_delay+0x0/0x0
> >>>>>>[    4.089513] initcall autoboot_delay+0x0/0x0 returned 0 after 1105 msecs.
> >>>>>>[    4.089513] calling  load_kernel+0x0/0x0
> >>>>>>[    4.239174] initcall load_kernel+0x0/0x0 returned 0 after 149 msecs.
> >>>>>>[    4.239174] calling  boot_kernel+0x0/0x0
> >>>>>>[    4.276260] initcall boot_kernel+0x0/0x0 returned 0 after 37 msecs.
> >>>>>>[    4.276260] calling  uncompress_ll_init+0x0/0x0
> >>>>>>[    4.276260] initcall uncompress_ll_init+0x0/0x0 returned 0 after 0 msecs.
> >>>>>>[    4.276260] Freeing init memory: 0K

> >commit 4c49a18bcfd2d041cbad7f41c6e6b39d90008382 (HEAD, refs/heads/dt-snowball-pre-rc1)
> >Author: Jonas Aaberg<jonas.aberg@stericsson.com>
> >Date:   Wed Sep 14 09:29:20 2011 +0200
> >
> >     drivers: clocksource: dbx500-prcmu: Add boottime support
> >
> >     Change-Id: I9b5e3d050131c08c08786ae84cb76619c0525049
> >     Signed-off-by: Jonas Aaberg<jonas.aberg@stericsson.com>
> >     Reviewed-on: http://gerrit.lud.stericsson.com/gerrit/32055
> >
> >diff --git a/drivers/clocksource/clksrc-dbx500-prcmu.c b/drivers/clocksource/clksrc-dbx500-prcmu.c
> >index c26c369..0069cd9 100644
> >--- a/drivers/clocksource/clksrc-dbx500-prcmu.c
> >+++ b/drivers/clocksource/clksrc-dbx500-prcmu.c
> >@@ -14,6 +14,7 @@
> >   */
> >  #include<linux/clockchips.h>
> >  #include<linux/clksrc-dbx500-prcmu.h>
> >+#include<linux/boottime.h>
> >
> >  #include<asm/sched_clock.h>
> >
> >@@ -68,6 +69,23 @@ static u32 notrace dbx500_prcmu_sched_clock_read(void)
> >
> >  #endif
> >
> >+#ifdef CONFIG_BOOTTIME
> >+static unsigned long __init boottime_get_time(void)
> >+{
> >+	return div_s64(clocksource_cyc2ns(clocksource_dbx500_prcmu.read(
> >+						&clocksource_dbx500_prcmu),
> >+					  clocksource_dbx500_prcmu.mult,
> >+					  clocksource_dbx500_prcmu.shift),
> >+		       1000);
> >+}
> >+
> >+static struct boottime_timer __initdata boottime_timer = {
> >+	.init     = NULL,
> >+	.get_time = boottime_get_time,
> >+	.finalize = NULL,
> >+};
> >+#endif
> >+
> >  void __init clksrc_dbx500_prcmu_init(void __iomem *base)
> >  {
> >  	clksrc_dbx500_timer_base = base;
> >@@ -90,4 +108,6 @@ void __init clksrc_dbx500_prcmu_init(void __iomem *base)
> >  			 32, RATE_32K);
> >  #endif
> >  	clocksource_register_hz(&clocksource_dbx500_prcmu, RATE_32K);
> >+
> >+	boottime_activate(&boottime_timer);
> >  }
> >
> 
> OK So has this been validated and tested on any other IC then a ST part?
> This boottime_activate patch seems to be only for the dbx500.  If
> this is supposed to be a generic solution I would expect
> a generic patch for ARM to enable boot time activation.

No, this is essentially an STE patch. We don't have access to any other
hardware, so we'd be reliant on kindhearted soles to test on their h/w.
I guess something like Beagleboard and/or Panda would be ideal. Know
anyone? ;)

> Have you profiled how much time the boot time logging has added to
> the over all boot?
> Also the boottime commit message should explain a little more what
> it is measuring.
> i.e.  This patch enables logging the boot time from point x to point
> y for the kernel only.  This does not include init.
> 
> What about adding the boot time from the init sequence to init complete?

I don't know the answers to these questions, but I'll endeavour to find
out and get back to you posthaste.
Lee Jones Oct. 23, 2012, 7:19 a.m. UTC | #3 
I have a few answers for you.

> >>>>>>root@ME:/ cat /sys/kernel/debug/boottime/bootgraph
> >>>>>>[    0.185254] calling  splash+0x0/0x0
> >>>>>>[    2.984335] initcall splash+0x0/0x0 returned 0 after 2799 msecs.
> >>>>>>[    2.984335] calling  autoboot_delay+0x0/0x0
> >>>>>>[    4.089513] initcall autoboot_delay+0x0/0x0 returned 0 after 1105 msecs.
> >>>>>>[    4.089513] calling  load_kernel+0x0/0x0
> >>>>>>[    4.239174] initcall load_kernel+0x0/0x0 returned 0 after 149 msecs.
> >>>>>>[    4.239174] calling  boot_kernel+0x0/0x0
> >>>>>>[    4.276260] initcall boot_kernel+0x0/0x0 returned 0 after 37 msecs.
> >>>>>>[    4.276260] calling  uncompress_ll_init+0x0/0x0
> >>>>>>[    4.276260] initcall uncompress_ll_init+0x0/0x0 returned 0 after 0 msecs.
> >>>>>>[    4.276260] Freeing init memory: 0K

> OK So has this been validated and tested on any other IC then a ST part?

No, it has not. As I believe I mentioned before, this is a tool
written for and used by ST-Ericsson. Extending it to use on other
platforms sounds like a great idea, but won't be done by
ST-Ericsson due to a lack of hardware and software assets.

> This boottime_activate patch seems to be only for the dbx500.  If
> this is supposed to be a generic solution I would expect
> a generic patch for ARM to enable boot time activation.

Apparently a generic boottime extention would be fairly trivial
with the use of ktime_get().

> Have you profiled how much time the boot time logging has added to
> the over all boot?

This has not been completed, but the original author suspects
it would be <100ms.

> Also the boottime commit message should explain a little more what
> it is measuring.
> i.e.  This patch enables logging the boot time from point x to point
> y for the kernel only.  This does not include init.
> What about adding the boot time from the init sequence to init complete?

This sounds like a good idea, but again won't be extended upon by
us.

It appears that this driver is interesting and possibly very
useful for quite a lot of people out there. This patch should
therefore be seen as the foundations for other to then extend
in the ways alluded to above and ported to work on other more
generic platforms. I think these should be extra patches on
top of the one submitted here.

From a personal perspective, I am happy to change a few bits
and pieces, but I don't have the time to satisfy all of the
suggestions made, or adapt the driver in any substantial
manor.
diff mbox

Patch

diff --git a/drivers/clocksource/clksrc-dbx500-prcmu.c b/drivers/clocksource/clksrc-dbx500-prcmu.c
index c26c369..0069cd9 100644
--- a/drivers/clocksource/clksrc-dbx500-prcmu.c
+++ b/drivers/clocksource/clksrc-dbx500-prcmu.c
@@ -14,6 +14,7 @@ 
  */
 #include <linux/clockchips.h>
 #include <linux/clksrc-dbx500-prcmu.h>
+#include <linux/boottime.h>
 
 #include <asm/sched_clock.h>
 
@@ -68,6 +69,23 @@  static u32 notrace dbx500_prcmu_sched_clock_read(void)
 
 #endif
 
+#ifdef CONFIG_BOOTTIME
+static unsigned long __init boottime_get_time(void)
+{
+	return div_s64(clocksource_cyc2ns(clocksource_dbx500_prcmu.read(
+						  &clocksource_dbx500_prcmu),
+					  clocksource_dbx500_prcmu.mult,
+					  clocksource_dbx500_prcmu.shift),
+		       1000);
+}
+
+static struct boottime_timer __initdata boottime_timer = {
+	.init     = NULL,
+	.get_time = boottime_get_time,
+	.finalize = NULL,
+};
+#endif
+
 void __init clksrc_dbx500_prcmu_init(void __iomem *base)
 {
 	clksrc_dbx500_timer_base = base;
@@ -90,4 +108,6 @@  void __init clksrc_dbx500_prcmu_init(void __iomem *base)
 			 32, RATE_32K);
 #endif
 	clocksource_register_hz(&clocksource_dbx500_prcmu, RATE_32K);
+
+	boottime_activate(&boottime_timer);
 }