[PATCH] add a counter in grub_dprintf

[PATCH] add a counter in grub_dprintf

[Robert Millan]

[-- Attachment #1: Type: text/plain, Size: 549 bytes --]


How about adding a counter to grub_dprintf to make it easy to instrument
GRUB and find which are the bottlenecks in boot time?

Sidenote: perhaps it'd be a good idea to conditionalize all grub_dprintf
calls with #ifdef DEBUG to obtain a smaller core.img.  It's not hard to
ask a user to rebuild if dprintf is needed, and we can find non-ugly ways
to do this without massive #ifdefs all over the code.

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

[-- Attachment #2: counter.diff --]
[-- Type: text/x-diff, Size: 1737 bytes --]

diff -x ChangeLog -x configure -x config.h.in -x CVS -x '*~' -x '*.mk' -urp ../grub2/include/grub/time.h ./include/grub/time.h
--- ../grub2/include/grub/time.h	2007-10-22 22:02:16.000000000 +0200
+++ ./include/grub/time.h	2008-06-19 15:23:45.000000000 +0200
@@ -23,6 +23,8 @@
 #include <grub/machine/time.h>
 #include <grub/cpu/time.h>
 
+extern grub_uint32_t grub_start_time;
+
 void EXPORT_FUNC(grub_millisleep) (grub_uint32_t ms);
 void EXPORT_FUNC(grub_millisleep_generic) (grub_uint32_t ms);
 
diff -x ChangeLog -x configure -x config.h.in -x CVS -x '*~' -x '*.mk' -urp ../grub2/kern/main.c ./kern/main.c
--- ../grub2/kern/main.c	2008-02-10 18:05:10.000000000 +0100
+++ ./kern/main.c	2008-06-19 15:19:45.000000000 +0200
@@ -106,12 +106,15 @@ grub_load_normal_mode (void)
   grub_print_error ();
 }
 
+grub_uint32_t grub_start_time;
+
 /* The main routine.  */
 void
 grub_main (void)
 {
   /* First of all, initialize the machine.  */
   grub_machine_init ();
+  grub_start_time = grub_get_rtc ();
 
   /* Hello.  */
   grub_setcolorstate (GRUB_TERM_COLOR_HIGHLIGHT);
diff -x ChangeLog -x configure -x config.h.in -x CVS -x '*~' -x '*.mk' -urp ../grub2/kern/misc.c ./kern/misc.c
--- ../grub2/kern/misc.c	2008-06-16 22:11:22.000000000 +0200
+++ ./kern/misc.c	2008-06-19 15:26:40.000000000 +0200
@@ -147,7 +147,15 @@ grub_real_dprintf (const char *file, con
   
   if (grub_strword (debug, "all") || grub_strword (debug, condition))
     {
-      grub_printf ("%s:%d: ", file, line);
+      grub_printf (
+#ifndef GRUB_UTIL
+		   "[%u] "
+#endif
+		   "%s:%d: ",
+#ifndef GRUB_UTIL
+		   grub_get_rtc () - grub_start_time,
+#endif
+		   file, line);
       va_start (args, fmt);
       grub_vprintf (fmt, args);
       va_end (args);

Re: [PATCH] add a counter in grub_dprintf

[Isaac Dupree]

Robert Millan wrote:
> How about adding a counter to grub_dprintf to make it easy to instrument
> GRUB and find which are the bottlenecks in boot time?
> 
> Sidenote: perhaps it'd be a good idea to conditionalize all grub_dprintf
> calls with #ifdef DEBUG to obtain a smaller core.img.  It's not hard to
> ask a user to rebuild if dprintf is needed,

Are the dprintf's useful for users' debugging, not just debugging GRUB 
bugs?  If it is, I'm not sure... If I accidentally broke something on my 
disk so that the core image couldn't find the modules/configuration, 
then it might be a little hard to rebuild grub and reinstall on that 
machine.  Obviously I'll be able to, somehow, if my computer isn't 
completely hosed, but I'd rather be able to search for debugging 
information I recorded ASAP so I need fewer iterations of nuisance for 
myself.  Perhaps a minor issue.

-Isaac

Re: [PATCH] add a counter in grub_dprintf

[Robert Millan]

On Thu, Jun 19, 2008 at 02:42:34PM -0400, Isaac Dupree wrote:
> Robert Millan wrote:
> >How about adding a counter to grub_dprintf to make it easy to instrument
> >GRUB and find which are the bottlenecks in boot time?
> >
> >Sidenote: perhaps it'd be a good idea to conditionalize all grub_dprintf
> >calls with #ifdef DEBUG to obtain a smaller core.img.  It's not hard to
> >ask a user to rebuild if dprintf is needed,
> 
> Are the dprintf's useful for users' debugging, not just debugging GRUB 
> bugs?  If it is, I'm not sure... If I accidentally broke something on my 
> disk so that the core image couldn't find the modules/configuration, 
> then it might be a little hard to rebuild grub and reinstall on that 
> machine.  Obviously I'll be able to, somehow, if my computer isn't 
> completely hosed, but I'd rather be able to search for debugging 
> information I recorded ASAP so I need fewer iterations of nuisance for 
> myself.  Perhaps a minor issue.

dprintf can be useful for debugging, but not for fixing the problem (except
maybe in very rare situations).  So if your system can't boot, it's not
going to change much.

Most users won't know about grub_dprintf untill they're told to use it to
send a debug trace;  so in a typical situation they would still have to boot
their system somehow, in order to send us a bug report.

OTOH, it could add maintainance burden for us when we have to explain
everyone that they have to rebuild and reinstall GRUB to get the debug
output _and_ it opens the door for heisenbugs.

But space in post-mbr area is precious, and if we can save a bit, it means
less users who will run into trouble in first place.

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

Re: [PATCH] add a counter in grub_dprintf

[Javier Martín]

[-- Attachment #1: Type: text/plain, Size: 1422 bytes --]

El sáb, 21-06-2008 a las 16:19 +0200, Robert Millan escribió:
> But space in post-mbr area is precious, and if we can save a bit, it means
> less users who will run into trouble in first place.
> 

Disclaimer: the following is just the product of brainstorming from a
mind tortured by hours of studying projective geometry. Use with care ^^

Why not modify the build system to create _two_ instances of kernel.img,
one with and another without debugging? grub_mkimage would create the
normal, smaller core.img (without dprintf) for installing and embedding;
and store a core_dbg.img in the /boot/grub folder, so that if
instrumentation is required the only thing the users needs to do is
chain that debug version of GRUB:

    grub> multiboot /boot/grub/core_dbg.img
    grub> boot

Another option would be to separate grub_dprintf into a module of its
own that could, or could not, go into core.img depending on space
pressure. We'd still need a "grub_dprintf" in the kernel, but it would
just reduce to "Is debug.mod loaded? Yes->call debug_grub_dprintf". This
would only result in a substantial reduction of kernel if grub_dprintf
is currently a big function (and I haven't even taken a look at it) with
format substitution and all. The downside is that we'd have no dprintf
at all until modules are loaded, though some logic can be hardcoded so
that debug.mod is loaded first, if present.

[-- Attachment #2: Esta parte del mensaje está firmada digitalmente --]
[-- Type: application/pgp-signature, Size: 827 bytes --]

Re: [PATCH] add a counter in grub_dprintf

[Bram Diederik]

On Sat, Jun 21, 2008 at 4:35 PM, Javier Martín <lordhabbit@gmail.com> wrote:
> El sáb, 21-06-2008 a las 16:19 +0200, Robert Millan escribió:
>> But space in post-mbr area is precious, and if we can save a bit, it means
>> less users who will run into trouble in first place.
>>
>
> Disclaimer: the following is just the product of brainstorming from a
> mind tortured by hours of studying projective geometry. Use with care ^^
>
> Why not modify the build system to create _two_ instances of kernel.img,
> one with and another without debugging? grub_mkimage would create the
> normal, smaller core.img (without dprintf) for installing and embedding;
> and store a core_dbg.img in the /boot/grub folder, so that if
> instrumentation is required the only thing the users needs to do is
> chain that debug version of GRUB:
>
>    grub> multiboot /boot/grub/core_dbg.img
>    grub> boot
>
> Another option would be to separate grub_dprintf into a module of its
> own that could, or could not, go into core.img depending on space
> pressure. We'd still need a "grub_dprintf" in the kernel, but it would
> just reduce to "Is debug.mod loaded? Yes->call debug_grub_dprintf". This
> would only result in a substantial reduction of kernel if grub_dprintf
> is currently a big function (and I haven't even taken a look at it) with
> format substitution and all. The downside is that we'd have no dprintf
> at all until modules are loaded, though some logic can be hardcoded so
> that debug.mod is loaded first, if present.
>
> _______________________________________________
> Grub-devel mailing list
> Grub-devel@gnu.org
> http://lists.gnu.org/mailman/listinfo/grub-devel
>
>

Or a set-grub-debug command that triggers grub to debug (load debug
module) on next boot. If you're already going to hard code something.
(you can set the next default boot so why not this)

Looks very logical to me.
You're only going (and want) to debug when something went wrong.
(except devels)
its also the most user friendly way. you can set that flag from grub or any OS.
giving you info you need but normally don't want to see.

Re: [PATCH] add a counter in grub_dprintf

[Isaac Dupree]

Javier Martín wrote:
> El sáb, 21-06-2008 a las 16:19 +0200, Robert Millan escribió:
>> But space in post-mbr area is precious, and if we can save a bit, it means
>> less users who will run into trouble in first place.
>>
> 
> Disclaimer: the following is just the product of brainstorming from a
> mind tortured by hours of studying projective geometry. Use with care ^^
> 
> Why not modify the build system to create _two_ instances of kernel.img,
> one with and another without debugging? grub_mkimage would create the
> normal, smaller core.img (without dprintf) for installing and embedding;
> and store a core_dbg.img in the /boot/grub folder, so that if
> instrumentation is required the only thing the users needs to do is
> chain that debug version of GRUB:
> 
>     grub> multiboot /boot/grub/core_dbg.img
>     grub> boot

or even to install it if necessary (if it fits! But multiboot, if it 
works, could help *some* of the time too).  I think that prebuilt debug 
image is important, otherwise when users rebuild a debug version it's 
much more likely to be built differently somehow from the corresponding 
non-debug version (especially if it originally came through a packaging 
system such as Debian).


Robert Millan wrote:
> OTOH, it could add maintainance burden for us when we have to explain
> everyone that they have to rebuild and reinstall GRUB to get the debug
> output _and_ it opens the door for heisenbugs.
> 
> But space in post-mbr area is precious, and if we can save a bit, it means
> less users who will run into trouble in first place.

the possibility for heisenbugs does seem very real given the diversity 
of hardware out there.  Would it mitigate this to only disable the 
dprintfs (by default) in space-critical images such as x86 pc?  (or 
would it make things worse...)

-Isaac

Re: [PATCH] add a counter in grub_dprintf

[Robert Millan]

On Sat, Jun 21, 2008 at 04:35:07PM +0200, Javier Martín wrote:
> 
> Why not modify the build system to create _two_ instances of kernel.img,
> one with and another without debugging? grub_mkimage would create the
> normal, smaller core.img (without dprintf) for installing and embedding;
> and store a core_dbg.img in the /boot/grub folder,

This breaks the design and forces grub-mkimage to have:

  a) knowledge about GRUB paths

  b) requirement for root perms

instead of just being an utility to generate images.  I don't think it's
a good idea.

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

Re: [PATCH] add a counter in grub_dprintf

[Javier Martín]

[-- Attachment #1: Type: text/plain, Size: 1143 bytes --]

El jue, 26-06-2008 a las 16:08 +0200, Robert Millan escribió:
> On Sat, Jun 21, 2008 at 04:35:07PM +0200, Javier Martín wrote:
> > 
> > Why not modify the build system to create _two_ instances of kernel.img,
> > one with and another without debugging? grub_mkimage would create the
> > normal, smaller core.img (without dprintf) for installing and embedding;
> > and store a core_dbg.img in the /boot/grub folder,
> 
> This breaks the design and forces grub-mkimage to have:
> 
>   a) knowledge about GRUB paths
> 
>   b) requirement for root perms
> 
> instead of just being an utility to generate images.  I don't think it's
> a good idea.
> 
Whoops, sorry, I meant that grub_mkimage would create two core.img
images, one per kernel.img version, and then grub_install would copy
them as usual. Then grub_setup would embed/set up the normal core.img
or the debug version based on a switch. What I propose is basically
modifying grub_mkimage to allow choosing the kernel.img file used and
then adding some lines to grub_install so that the two versions of
core.img are generated (but only the selected is embedded).

[-- Attachment #2: Esta parte del mensaje está firmada digitalmente --]
[-- Type: application/pgp-signature, Size: 827 bytes --]

Re: [PATCH] add a counter in grub_dprintf

[Robert Millan]

On Thu, Jun 26, 2008 at 05:20:51PM +0200, Javier Martín wrote:
> El jue, 26-06-2008 a las 16:08 +0200, Robert Millan escribió:
> > On Sat, Jun 21, 2008 at 04:35:07PM +0200, Javier Martín wrote:
> > > 
> > > Why not modify the build system to create _two_ instances of kernel.img,
> > > one with and another without debugging? grub_mkimage would create the
> > > normal, smaller core.img (without dprintf) for installing and embedding;
> > > and store a core_dbg.img in the /boot/grub folder,
> > 
> > This breaks the design and forces grub-mkimage to have:
> > 
> >   a) knowledge about GRUB paths
> > 
> >   b) requirement for root perms
> > 
> > instead of just being an utility to generate images.  I don't think it's
> > a good idea.
> > 
> Whoops, sorry, I meant that grub_mkimage would create two core.img
> images, one per kernel.img version, and then grub_install would copy
> them as usual. Then grub_setup would embed/set up the normal core.img
> or the debug version based on a switch. What I propose is basically
> modifying grub_mkimage to allow choosing the kernel.img file used and
> then adding some lines to grub_install so that the two versions of
> core.img are generated (but only the selected is embedded).

Ah;  then it sounds fine, I guess.

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

Re: [PATCH] add a counter in grub_dprintf

[Pavel Roskin]

On Sun, 2008-06-29 at 13:22 +0200, Robert Millan wrote:
> On Thu, Jun 26, 2008 at 05:20:51PM +0200, Javier Martín wrote:

> > Whoops, sorry, I meant that grub_mkimage would create two core.img
> > images, one per kernel.img version, and then grub_install would copy
> > them as usual. Then grub_setup would embed/set up the normal core.img
> > or the debug version based on a switch. What I propose is basically
> > modifying grub_mkimage to allow choosing the kernel.img file used and
> > then adding some lines to grub_install so that the two versions of
> > core.img are generated (but only the selected is embedded).
> 
> Ah;  then it sounds fine, I guess.

Sorry for entering this discussion so late.  I can tell from my
experience that most debug code is only useful to debug once specific
problem.  Once the problem is fixed, the debug code is not needed.  If
another problem is found, then some new debug code should be written to
debug that problem.

Generic debug code may be useful to get information from users if only
they can reproduce the problem.  But even then, if may be better to add
a few lines to test certain assumptions rather than try to glean useful
pieces of information from a long generic log.

Adding a complicated mechanism for having debug and non-debug images
looks like an overkill to me.  It could create more problems than it
would fix.

-- 
Regards,
Pavel Roskin

Re: [PATCH] add a counter in grub_dprintf

[Vesa Jääskeläinen]

Pavel Roskin wrote:
> On Sun, 2008-06-29 at 13:22 +0200, Robert Millan wrote:
>> On Thu, Jun 26, 2008 at 05:20:51PM +0200, Javier Martín wrote:
> 
>>> Whoops, sorry, I meant that grub_mkimage would create two core.img
>>> images, one per kernel.img version, and then grub_install would copy
>>> them as usual. Then grub_setup would embed/set up the normal core.img
>>> or the debug version based on a switch. What I propose is basically
>>> modifying grub_mkimage to allow choosing the kernel.img file used and
>>> then adding some lines to grub_install so that the two versions of
>>> core.img are generated (but only the selected is embedded).
>> Ah;  then it sounds fine, I guess.
> 
> Sorry for entering this discussion so late.  I can tell from my
> experience that most debug code is only useful to debug once specific
> problem.  Once the problem is fixed, the debug code is not needed.  If
> another problem is found, then some new debug code should be written to
> debug that problem.
> 
> Generic debug code may be useful to get information from users if only
> they can reproduce the problem.  But even then, if may be better to add
> a few lines to test certain assumptions rather than try to glean useful
> pieces of information from a long generic log.
> 
> Adding a complicated mechanism for having debug and non-debug images
> looks like an overkill to me.  It could create more problems than it
> would fix.

One way to proceed here is to use debugger for the original benchmarking 
purpose.

You would put timed breakpoints, when breakpoint is found, time would be 
recorded and then execution would be automatically continued. This can 
be almost fully external to the code being executed.

Re: [PATCH] add a counter in grub_dprintf

[Robert Millan]

On Mon, Jun 30, 2008 at 01:13:34PM -0400, Pavel Roskin wrote:
> On Sun, 2008-06-29 at 13:22 +0200, Robert Millan wrote:
> > On Thu, Jun 26, 2008 at 05:20:51PM +0200, Javier Martín wrote:
> 
> > > Whoops, sorry, I meant that grub_mkimage would create two core.img
> > > images, one per kernel.img version, and then grub_install would copy
> > > them as usual. Then grub_setup would embed/set up the normal core.img
> > > or the debug version based on a switch. What I propose is basically
> > > modifying grub_mkimage to allow choosing the kernel.img file used and
> > > then adding some lines to grub_install so that the two versions of
> > > core.img are generated (but only the selected is embedded).
> > 
> > Ah;  then it sounds fine, I guess.
> 
> Sorry for entering this discussion so late.  I can tell from my
> experience that most debug code is only useful to debug once specific
> problem.  Once the problem is fixed, the debug code is not needed.  If
> another problem is found, then some new debug code should be written to
> debug that problem.
> 
> Generic debug code may be useful to get information from users if only
> they can reproduce the problem.  But even then, if may be better to add
> a few lines to test certain assumptions rather than try to glean useful
> pieces of information from a long generic log.

Ironicaly, this was also true for my original purpose of measuring performance
during boot.  The standard dprintf calls ate so much time (because of the
serial terminal) that they didn't provide any useful output of the time spent
doing something else.

In the end, I had to add custom calls to print time in the specific places
where I wanted them.

> Adding a complicated mechanism for having debug and non-debug images
> looks like an overkill to me.  It could create more problems than it
> would fix.

But then, what do you suggest?  That we remove debug support altogether?

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

Re: [PATCH] add a counter in grub_dprintf

[Robert Millan]

On Mon, Jun 30, 2008 at 08:33:45PM +0300, Vesa Jääskeläinen wrote:
> 
> One way to proceed here is to use debugger for the original benchmarking 
> purpose.
> 
> You would put timed breakpoints, when breakpoint is found, time would be 
> recorded and then execution would be automatically continued. This can 
> be almost fully external to the code being executed.

You mean gdb over serial terminal?  Never tried this.  Does it work well with
GRUB?

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

Re: [PATCH] add a counter in grub_dprintf

[Pavel Roskin]

On Tue, 2008-07-01 at 17:59 +0200, Robert Millan wrote:

> > Adding a complicated mechanism for having debug and non-debug images
> > looks like an overkill to me.  It could create more problems than it
> > would fix.
> 
> But then, what do you suggest?  That we remove debug support altogether?

Keep what we have unless we are under pressure to remove it.  Add new
stuff only if it's likely to help debugging more than one bug.

-- 
Regards,
Pavel Roskin

Re: [PATCH] add a counter in grub_dprintf

[Robert Millan]

On Tue, Jul 01, 2008 at 12:01:57PM -0400, Pavel Roskin wrote:
> On Tue, 2008-07-01 at 17:59 +0200, Robert Millan wrote:
> 
> > > Adding a complicated mechanism for having debug and non-debug images
> > > looks like an overkill to me.  It could create more problems than it
> > > would fix.
> > 
> > But then, what do you suggest?  That we remove debug support altogether?
> 
> Keep what we have unless we are under pressure to remove it.

We _are_ under pressure.  Some setups are too big for core.img to fit in
post-MBR region already.

-- 
Robert Millan

<GPLv2> I know my rights; I want my phone call!
<DRM> What good is a phone call… if you are unable to speak?
(as seen on /.)

Re: [PATCH] add a counter in grub_dprintf

[Pavel Roskin]

On Tue, 2008-07-01 at 19:19 +0200, Robert Millan wrote:
> On Tue, Jul 01, 2008 at 12:01:57PM -0400, Pavel Roskin wrote:
> > On Tue, 2008-07-01 at 17:59 +0200, Robert Millan wrote:
> > 
> > > > Adding a complicated mechanism for having debug and non-debug images
> > > > looks like an overkill to me.  It could create more problems than it
> > > > would fix.
> > > 
> > > But then, what do you suggest?  That we remove debug support altogether?
> > 
> > Keep what we have unless we are under pressure to remove it.
> 
> We _are_ under pressure.  Some setups are too big for core.img to fit in
> post-MBR region already.

Then parts of the debugging code that goes into core.img should be good
candidates for removal.  However, we could probably start with lzma
conversion (or did we pick gzip?)

-- 
Regards,
Pavel Roskin

Re: [PATCH] add a counter in grub_dprintf

[Marco Gerards]

Robert Millan <rmh@aybabtu.com> writes:

> How about adding a counter to grub_dprintf to make it easy to instrument
> GRUB and find which are the bottlenecks in boot time?
>
> Sidenote: perhaps it'd be a good idea to conditionalize all grub_dprintf
> calls with #ifdef DEBUG to obtain a smaller core.img.  It's not hard to
> ask a user to rebuild if dprintf is needed, and we can find non-ugly ways
> to do this without massive #ifdefs all over the code.

How about a configure time switch to *disable* dprintf.  I prefer to
have it enabled by default.  In that case distributions can create two
packages.  One for normal use and one for debugging.

--
Marco