Why does booting time reduce from 2 min to 1 min after just adding a printk(..) invoking?

74 views
Skip to first unread message

Gary

unread,
Jun 16, 2010, 11:21:30 AM6/16/10
to Android Linux Kernel Development
Hi, all

Now my device needs 2 minutes to boot up.
But I found that the booting time will be reduced to 1 minute after I
add just a printk(..) invoking as shown below.
Even though the booting time has been reduced by adding one line of
routine,but I have not found the real reason why the device needs 2
minutes to boot up.

Do you have any ideas or suggestions on my question?

/linux2.6.29/init/main.c

static void __init do_initcalls(void)
{
initcall_t *call;
for (call = __early_initcall_end; call < __initcall_end; call++){
do_one_initcall(*call);
printk("yangwd, do it,0x%x\r\n",call); // just add this line of
routine
}
/* Make sure there is no pending stuff from the initcall sequence */
flush_scheduled_work();
}

Thanks

Gary

Greg KH

unread,
Jun 18, 2010, 1:50:01 PM6/18/10
to android...@googlegroups.com
On Wed, Jun 16, 2010 at 8:21 AM, Gary <gary0...@gmail.com> wrote:
> Hi, all
>
> Now my device needs 2 minutes to boot up.
> But I found that the booting time will be reduced to 1 minute after I
> add just a printk(..) invoking as shown below.
> Even though the booting time has been reduced by adding one line of
> routine,but I have not found the real reason why the device needs 2
> minutes to boot up.
>
> Do you have any ideas or suggestions on my question?
>
> /linux2.6.29/init/main.c
>
> static void __init do_initcalls(void)
> {
>        initcall_t *call;
>        for (call = __early_initcall_end; call < __initcall_end; call++){
>                do_one_initcall(*call);
> printk("yangwd, do it,0x%x\r\n",call); // just add this line of
> routine

Have you tried enabling the debugging for init calls so you can see where
the time is spent during booting? The documentation in the kernel shows
how to do this and how to generate pretty graphs showing what is going
on as well with the output.

good luck,

greg k-h

Tim Bird

unread,
Jun 18, 2010, 2:02:13 PM6/18/10
to android...@googlegroups.com, Gary

Well, as Greg said, the first thing you should do is use initcall_debug.
See http://elinux.org/Initcall_Debug

Also, try turning on timestamps for printks with "time" on the kernel
command line. See http://elinux.org/Printk_Times

Is it the kernel that's taking 2 minutes, or the whole system?

Note that on Android, the very first boot of a newly installed system
will take a very long time, due to building a dalvik cache of pre-processed
classes.

Just inserting a single printk in the initcall loop shouldn't have
any effect on bootup time.

If you're still seeing funny stuff after turning on some more
timing debugging info, please send you kernel message log output.
-- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Network Entertainment
=============================

xlshe

unread,
Jun 19, 2010, 1:08:32 AM6/19/10
to Android Linux Kernel Development
Hi, Gary

I am starting to do something in the kernel. But I don't know how to
read the information from the printk() in android phone OS. Because I
cann't find /var/log/syslog in the file system. Can you can me some
sugesstion about how to read the log from printk(). Thank you very
much.

Longsheng

Gary

unread,
Jun 19, 2010, 6:37:47 AM6/19/10
to Android Linux Kernel Development
Hi,Tim and Greg
Thanks for your information.
I used Initcall_Debug flag and found that the initialization of FFUART
takes about 4 seconds.
By tracing step by step, found the time ran away in
release_console_sem() function, located at printk.c.
I am confused why release_console_sem() took so long time.
Is there any other driver invoked release_console_sem() and did not
exited during its initializing before FFUART is initialized?

Not just kernel but the whole system takes 2 minutes to boot up.
Today, I added a the same log output after do_one_initcall(*call), but
2 minutes also are needed.
The result is different from what I have got before.It's so strange.
and while booting up, I found there are several times that no kernel
log information is outputted until after about 4 or 5 seconds.
Because there is no kernel log at the moment, I don't know what the
kernel was doing.
Maybe 2 minutes of booting time was caused by these several times of 4
or 5 seconds.
Except for log information, Are there any other methods to know what
the kernel was doing during no-log phase of kernel booting?

Thank you


On 6月19日, 上午2时02分, Tim Bird <tim.b...@am.sony.com> wrote:
> On 06/16/2010 08:21 AM, Gary wrote:
>
>
>
>
>
> > Hi, all
>
> > Now my device needs 2 minutes to boot up.
> > But I found that the booting time will be reduced to 1 minute after I
> > add just a printk(..) invoking as shown below.
> > Even though the booting time has been reduced by adding one line of
> > routine,but I have not found the real reason why the device needs 2
> > minutes to boot up.
>
> > Do you have any ideas or suggestions on my question?
>
> > /linux2.6.29/init/main.c
>
> > static void __init do_initcalls(void)
> > {
> >    initcall_t *call;
> >    for (call = __early_initcall_end; call < __initcall_end; call++){
> >            do_one_initcall(*call);
> > printk("yangwd, do it,0x%x\r\n",call); // just add this line of
> > routine
> >    }
> >    /* Make sure there is no pending stuff from the initcall sequence */
> >    flush_scheduled_work();
> > }
>
> Well, as Greg said, the first thing you should do is use initcall_debug.
> Seehttp://elinux.org/Initcall_Debug
>
> Also, try turning on timestamps for printks with "time" on the kernel
> command line. Seehttp://elinux.org/Printk_Times

Gary

unread,
Jun 19, 2010, 6:44:16 AM6/19/10
to Android Linux Kernel Development
Hi, Longsheng

I am using a special device by which capturing the log by UART and see
log in Hyper - Terminal.

and also you could try /var/log/dmesg.

sanjeev sharma

unread,
Jun 19, 2010, 6:54:00 PM6/19/10
to android...@googlegroups.com
on Android you should use dmesg after Android system boot's up and real time logs can be captured using connect to UART using minicom or hyperterminal.


sanjeev sharma


Tim Bird

unread,
Jun 21, 2010, 3:28:55 PM6/21/10
to android...@googlegroups.com, Gary
On 06/19/2010 03:37 AM, Gary wrote:
> Hi,Tim and Greg
> Thanks for your information.
> I used Initcall_Debug flag and found that the initialization of FFUART
> takes about 4 seconds.
> By tracing step by step, found the time ran away in
> release_console_sem() function, located at printk.c.
> I am confused why release_console_sem() took so long time.
> Is there any other driver invoked release_console_sem() and did not
> exited during its initializing before FFUART is initialized?

This sounds like something I've seen on other devices.

Try the kernel 'quiet' option. See http://elinux.org/Disable_Console

The kernel printk buffer (known internally as the "log buffer") is
filled will messages throughout the execution of the kernel.
However, these messages can not be printed out to the serial
port until the kernel initializes the serial console. When
the serial console is ready, all the messages that were previously
saved in the buffer are displayed at once. From then on, each
message that is "printk-ed" to the buffer is both saved in the
buffer, and also immediately displayed on the console.

This explains why 1) you see no messages for a little while
before the console is initialized 2) why there is a long delay
when the console is initialized, and the previoulsy buffered
messages are drained out to the serial port (which is usually slow).
BTW - what speed is your serial port? On most systems, draining
the queued messages to the serial console takes less than a half
second.

You can avoid this delay by turning off the message output to console
during booting. By using the 'quiet' option on the kernel command
line, the messages are saved in the log buffer, but not displayed.
They can be retrieved later using the 'dmesg' command on the target
(or 'adb dmesg' on the host). If you have printk times turned on,
you can see a timestamp on each message, which will allow you to see
when each message was printk-ed.

> Not just kernel but the whole system takes 2 minutes to boot up.
> Today, I added a the same log output after do_one_initcall(*call), but
> 2 minutes also are needed.
> The result is different from what I have got before.It's so strange.
> and while booting up, I found there are several times that no kernel
> log information is outputted until after about 4 or 5 seconds.
> Because there is no kernel log at the moment, I don't know what the
> kernel was doing.
> Maybe 2 minutes of booting time was caused by these several times of 4
> or 5 seconds.
> Except for log information, Are there any other methods to know what
> the kernel was doing during no-log phase of kernel booting?

On some ARM systems, the kernel has the capability to print directly to the
serial port (NOT going through the log buffer). These messages come
out on the serial console immediately when they are output by the code,
not later after buffering.

Set CONFIG_DEBUG_LL and add calls to printascii, printch and printhex.
Google CONFIG_DEBUG_LL for more information, and look at uses of
it in the kernel source tree.

I hope this helps.

radovan lekanovic

unread,
Jun 19, 2010, 2:09:43 AM6/19/10
to android...@googlegroups.com
Hi

You can use dmesg to see the printk logs. Just type "dmesg" or you can use adb like this: adb shell 'cat /proc/kmsg'

BR
Raso

2010/6/19 xlshe <dianyua...@gmail.com>
Reply all
Reply to author
Forward
0 new messages