Can jiffies freeze?

Can jiffies freeze?

[sandeep kumar]

Hi all
As far as I know jiffie counter is incremented HZ times/second. And it is
used to measure the time lapses in the kernel code.

I m seeing a case where, actualy time spent in some module using giffies is
zero, but while seeing UART logs i am seein 2 sec time difference. I dont
know how to interpret this. The case which i am seeing, hrtimers are not
enabled yet, so only thing i can rely are on jiffies.

My question here is,
Is it possible that the measured time lapse shown is "0"(jiffie count is
same before and after), but actually some time is spent?(say some 2 sec)

In another way..can jiffies may freeze for some time?

Please clarify...


-- 
With regards,
Sandeep Kumar Anantapalli,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130121/b4323c19/attachment.html 

Can jiffies freeze?

[anish singh]

On Tue, Jan 22, 2013 at 11:21 AM, sandeep kumar
<coolsandyforyou@gmail.com> wrote:
> Hi all
> As far as I know jiffie counter is incremented HZ times/second. And it is
> used to measure the time lapses in the kernel code.
>
> I m seeing a case where, actualy time spent in some module using giffies is
> zero, but while seeing UART logs i am seein 2 sec time difference. I dont
Please post the code here regarding how did you find out it is zero.
> know how to interpret this. The case which i am seeing, hrtimers are not
> enabled yet, so only thing i can rely are on jiffies.
>
> My question here is,
> Is it possible that the measured time lapse shown is "0"(jiffie count is
> same before and after), but actually some time is spent?(say some 2 sec)
>
> In another way..can jiffies may freeze for some time?
Is your watchdog enabled?If it is then you will see panic happening
i.e. soft lockup.
>
> Please clarify...
>
>
> --
> With regards,
> Sandeep Kumar Anantapalli,
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies at kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>

Re: Can jiffies freeze?

[anish singh]

On Tue, Jan 22, 2013 at 11:21 AM, sandeep kumar
<coolsandyforyou@gmail.com> wrote:
> Hi all
> As far as I know jiffie counter is incremented HZ times/second. And it is
> used to measure the time lapses in the kernel code.
>
> I m seeing a case where, actualy time spent in some module using giffies is
> zero, but while seeing UART logs i am seein 2 sec time difference. I dont
Please post the code here regarding how did you find out it is zero.
> know how to interpret this. The case which i am seeing, hrtimers are not
> enabled yet, so only thing i can rely are on jiffies.
>
> My question here is,
> Is it possible that the measured time lapse shown is "0"(jiffie count is
> same before and after), but actually some time is spent?(say some 2 sec)
>
> In another way..can jiffies may freeze for some time?
Is your watchdog enabled?If it is then you will see panic happening
i.e. soft lockup.
>
> Please clarify...
>
>
> --
> With regards,
> Sandeep Kumar Anantapalli,
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies@kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>

Can jiffies freeze?

[Mulyadi Santosa]

Hi..

On Tue, Jan 22, 2013 at 12:51 PM, sandeep kumar
<coolsandyforyou@gmail.com> wrote:
> Hi all
> As far as I know jiffie counter is incremented HZ times/second. And it is
> used to measure the time lapses in the kernel code.
>
> I m seeing a case where, actualy time spent in some module using giffies is
> zero,

theoritically possible, especially under NO_HZ a.k.a dynamic tick, but
mind you 2 secs is so long, so maybe something is not right.

BTW, like Anish says, how do you read it? It sounds like you read
cached value of jiffies...but that's just my guess...



-- 
regards,

Mulyadi Santosa
Freelance Linux trainer and consultant

blog: the-hydra.blogspot.com
training: mulyaditraining.blogspot.com

Can jiffies freeze?

[hejianet]

how about to check the disable/enable timer interrupt?
cat /proc/stat before/after 2 seconds?
On 2013-01-22 13:51, sandeep kumar wrote:
> Hi all
> As far as I know jiffie counter is incremented HZ times/second. And it is
> used to measure the time lapses in the kernel code.
>
> I m seeing a case where, actualy time spent in some module using giffies is
> zero, but while seeing UART logs i am seein 2 sec time difference. I dont
> know how to interpret this. The case which i am seeing, hrtimers are not
> enabled yet, so only thing i can rely are on jiffies.
>
> My question here is,
> Is it possible that the measured time lapse shown is "0"(jiffie count is
> same before and after), but actually some time is spent?(say some 2 sec)
>
> In another way..can jiffies may freeze for some time?
>
> Please clarify...
>
>
>
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies at kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

Can jiffies freeze?

[sandeep kumar]

Hi All
I am seeing this problem at the very early in the start_kernel-->
mm_init--> free_highpages, at that time nothing is up and kernel is running
in single thread.

Thanks
Sandeep


On Tue, Jan 22, 2013 at 1:07 AM, hejianet <hejianet@linux.vnet.ibm.com>wrote:

> how about to check the disable/enable timer interrupt?
> cat /proc/stat before/after 2 seconds?
> On 2013-01-22 13:51, sandeep kumar wrote:
> > Hi all
> > As far as I know jiffie counter is incremented HZ times/second. And it is
> > used to measure the time lapses in the kernel code.
> >
> > I m seeing a case where, actualy time spent in some module using giffies
> is
> > zero, but while seeing UART logs i am seein 2 sec time difference. I dont
> > know how to interpret this. The case which i am seeing, hrtimers are not
> > enabled yet, so only thing i can rely are on jiffies.
> >
> > My question here is,
> > Is it possible that the measured time lapse shown is "0"(jiffie count is
> > same before and after), but actually some time is spent?(say some 2 sec)
> >
> > In another way..can jiffies may freeze for some time?
> >
> > Please clarify...
> >
> >
> >
> >
> > _______________________________________________
> > Kernelnewbies mailing list
> > Kernelnewbies at kernelnewbies.org
> > http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>
>
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies at kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>



-- 
With regards,
Sandeep Kumar Anantapalli,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130122/27c64146/attachment.html 

Can jiffies freeze?

[sandeep kumar]

Dear Anish, Mulyadi,

this is how i read jiffies.

unsigned long start_time, end_time;
start_time = jiffies;
free_area(***);
end_time = jiffies;
printk("%ld", end_time-start_time);

I onserved jiffies getting incremented at different place, though

thanks
sandeep



On Tue, Jan 22, 2013 at 10:29 AM, sandeep kumar
<coolsandyforyou@gmail.com>wrote:

> Hi All
> I am seeing this problem at the very early in the start_kernel-->
> mm_init--> free_highpages, at that time nothing is up and kernel is running
> in single thread.
>
> Thanks
> Sandeep
>
>
> On Tue, Jan 22, 2013 at 1:07 AM, hejianet <hejianet@linux.vnet.ibm.com>wrote:
>
>> how about to check the disable/enable timer interrupt?
>> cat /proc/stat before/after 2 seconds?
>> On 2013-01-22 13:51, sandeep kumar wrote:
>> > Hi all
>> > As far as I know jiffie counter is incremented HZ times/second. And it
>> is
>> > used to measure the time lapses in the kernel code.
>> >
>> > I m seeing a case where, actualy time spent in some module using
>> giffies is
>> > zero, but while seeing UART logs i am seein 2 sec time difference. I
>> dont
>> > know how to interpret this. The case which i am seeing, hrtimers are not
>> > enabled yet, so only thing i can rely are on jiffies.
>> >
>> > My question here is,
>> > Is it possible that the measured time lapse shown is "0"(jiffie count is
>> > same before and after), but actually some time is spent?(say some 2 sec)
>> >
>> > In another way..can jiffies may freeze for some time?
>> >
>> > Please clarify...
>> >
>> >
>> >
>> >
>> > _______________________________________________
>> > Kernelnewbies mailing list
>> > Kernelnewbies at kernelnewbies.org
>> > http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>>
>>
>>
>> _______________________________________________
>> Kernelnewbies mailing list
>> Kernelnewbies at kernelnewbies.org
>> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
>>
>
>
>
> --
> With regards,
> Sandeep Kumar Anantapalli,
>



-- 
With regards,
Sandeep Kumar Anantapalli,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130122/332d56f4/attachment.html 

Can jiffies freeze?

[Mulyadi Santosa]

On Wed, Jan 23, 2013 at 1:36 AM, sandeep kumar
<coolsandyforyou@gmail.com> wrote:
> Dear Anish, Mulyadi,
>
> this is how i read jiffies.
>
> unsigned long start_time, end_time;
> start_time = jiffies;
> free_area(***);
> end_time = jiffies;
> printk("%ld", end_time-start_time);
>
> I onserved jiffies getting incremented at different place, though

and where exactly do you put that code?

Theoritically, it is possible that you put such code in interrupt
disabled code path, thus you see no jiffies increment. Another
possibility is that code (retrieving jiffies for both start_time and
end_time) ends faster than 1/HZ second, thus jiffies hasn't
incremented yet.

-- 
regards,

Mulyadi Santosa
Freelance Linux trainer and consultant

blog: the-hydra.blogspot.com
training: mulyaditraining.blogspot.com

Can jiffies freeze?

[Mulyadi Santosa]

On Mon, Jan 28, 2013 at 2:44 PM, sandeep kumar
<coolsandyforyou@gmail.com> wrote:
> I had put that in free_highpages() arch/arm/mm/init.c...
> By that time LPJ(loops for jiffies) also not calibrated...

hmm, so it's ARM....ok, so maybe I am not really sure about what I can
help here.

But, generally, free_highpages() should not disable timer interrupt
while working


-- 
regards,

Mulyadi Santosa
Freelance Linux trainer and consultant

blog: the-hydra.blogspot.com
training: mulyaditraining.blogspot.com

Can jiffies freeze?

[Valdis.Kletnieks at vt.edu]

On Tue, 22 Jan 2013 10:29:05 -0800, sandeep kumar said:

> I am seeing this problem at the very early in the start_kernel-->
> mm_init--> free_highpages, at that time nothing is up and kernel is running
> in single thread.

If you build a kernel with printk timestamps, you'll see that they all
come out like this:

[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.8.0-rc3-next-20130117-dirty (valdis at turing-police.cc.vt.edu) (gcc version 4.7.2 20121109 (Red Hat 4.7.2-9) (GCC) ) #49 SMP PREEMPT Thu Jan 17 13:25:28 EST 2013
[    0.000000] Command line: ro root=/dev/mapper/vg_blackice-root log_buf_len=2M vga=893 loglevel=4 threadirqs intel_iommu=off LANG=en_US.UTF-8
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009bbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009bc00-0x000000000009ffff] reserved
(100 or so more lines with same timestamp)
(now we finish memory init)
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.000000] __ex_table already sorted, skipping sort
[    0.000000] xsave: enabled xstate_bv 0x3, cntxt size 0x240
[    0.000000] Memory: 4015936k/4718592k available (6266k kernel code, 536744k absent, 165912k reserved, 7260k data, 576k init)
(more lines skipped)
[    0.000000]  memory used by lock dependency info: 5855 kB
[    0.000000]  per task-struct memory footprint: 1920 bytes
[    0.000000] hpet clockevent registered
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 2527.012 MHz processor
[    0.001004] Calibrating delay loop (skipped), value calculated using timer frequency.. 5054.02 BogoMIPS (lpj=2527012)
[    0.001009] pid_max: default: 32768 minimum: 301
[    0.001100] Security Framework initialized

It probably simply be that your code is running before the clock is started
by the kernel.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 865 bytes
Desc: not available
Url : http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130122/6ed2d603/attachment.bin 

Can jiffies freeze?

[sandeep kumar]

Hi Mr.Valdis
as you rightly mentioned,cat /proc/kmsg is showing the time stamps,
according to that it is 0ms only.
But when you see the same with UART there is 2sec delay in showing the next
log. i caught this while i m observing the UART logs with
"Terminaliranicca".

Since i m early in the mm_init, i cant use watchdog to detect it, hrtimers
i cant use..i am really thinking how to analyse this delay..

Thanks
Sandeep

On Tue, Jan 22, 2013 at 10:40 AM, <Valdis.Kletnieks@vt.edu> wrote:

> On Tue, 22 Jan 2013 10:29:05 -0800, sandeep kumar said:
>
> > I am seeing this problem at the very early in the start_kernel-->
> > mm_init--> free_highpages, at that time nothing is up and kernel is
> running
> > in single thread.
>
> If you build a kernel with printk timestamps, you'll see that they all
> come out like this:
>
> [    0.000000] Initializing cgroup subsys cpuset
> [    0.000000] Initializing cgroup subsys cpu
> [    0.000000] Linux version 3.8.0-rc3-next-20130117-dirty (
> valdis at turing-police.cc.vt.edu) (gcc version 4.7.2 20121109 (Red Hat
> 4.7.2-9) (GCC) ) #49 SMP PREEMPT Thu Jan 17 13:25:28 EST 2013
> [    0.000000] Command line: ro root=/dev/mapper/vg_blackice-root
> log_buf_len=2M vga=893 loglevel=4 threadirqs intel_iommu=off
> LANG=en_US.UTF-8
> [    0.000000] KERNEL supported cpus:
> [    0.000000]   Intel GenuineIntel
> [    0.000000] e820: BIOS-provided physical RAM map:
> [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009bbff]
> usable
> [    0.000000] BIOS-e820: [mem 0x000000000009bc00-0x000000000009ffff]
> reserved
> (100 or so more lines with same timestamp)
> (now we finish memory init)
> [    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304
> bytes)
> [    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152
> bytes)
> [    0.000000] __ex_table already sorted, skipping sort
> [    0.000000] xsave: enabled xstate_bv 0x3, cntxt size 0x240
> [    0.000000] Memory: 4015936k/4718592k available (6266k kernel code,
> 536744k absent, 165912k reserved, 7260k data, 576k init)
> (more lines skipped)
> [    0.000000]  memory used by lock dependency info: 5855 kB
> [    0.000000]  per task-struct memory footprint: 1920 bytes
> [    0.000000] hpet clockevent registered
> [    0.000000] tsc: Fast TSC calibration using PIT
> [    0.000000] tsc: Detected 2527.012 MHz processor
> [    0.001004] Calibrating delay loop (skipped), value calculated using
> timer frequency.. 5054.02 BogoMIPS (lpj=2527012)
> [    0.001009] pid_max: default: 32768 minimum: 301
> [    0.001100] Security Framework initialized
>
> It probably simply be that your code is running before the clock is started
> by the kernel.
>



-- 
With regards,
Sandeep Kumar Anantapalli,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130122/a06771a0/attachment.html 

Can jiffies freeze?

[Valdis.Kletnieks at vt.edu]

On Tue, 22 Jan 2013 11:32:19 -0800, sandeep kumar said:

> as you rightly mentioned,cat /proc/kmsg is showing the time stamps,
> according to that it is 0ms only.
> But when you see the same with UART there is 2sec delay in showing the next
> log. i caught this while i m observing the UART logs with
> "Terminaliranicca".

Oh, I could believe there's 2 seconds of time used up there that doesn't
show in kernel timestamps because the timers aren't started yet.

> Since i m early in the mm_init, i cant use watchdog to detect it, hrtimers
> i cant use..i am really thinking how to analyse this delay..

Time for some lateral thinking.. :)

Can you give us some specs on the hardware (in particular, the CPU type/speed
and how much RAM is installed)?  2 seconds on a 2Ghz CPU is about 4 billion
cycles.

Also, are you adding any code into the mm_init path? If so, what exactly
are you doing?

I wonder how early the kernel tracing and profiling stuff is enabled.  It may
be possible to boot a kernel that has function-call tracing enabled, which
would not have timing info, but if you see a function that's being called 500K
times that should only be called a dozen times, that's probably your problem :)
You'd probably want it with 'init=/bin/bash' and dump the stuff, as running to
multiuser will almost certainly roll the buffers and lose the info).

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 865 bytes
Desc: not available
Url : http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130122/c2bf557f/attachment-0001.bin 

Can jiffies freeze?

[sandeep kumar]

Hi Valdis,
Device specs: CPU: 1.7Ghz & RAM: 2GB.
We are not adding any code in the mm_init, All we do is reserve some memory
during the boot time and rest of the memory around 1.45GB we configure it
as HIGHMEM.

Can you give me any info on how to do the profiling of the function calls
during ealry booting in the kernel.

Thanks
Sandeep


On Tue, Jan 22, 2013 at 12:38 PM, <Valdis.Kletnieks@vt.edu> wrote:

> On Tue, 22 Jan 2013 11:32:19 -0800, sandeep kumar said:
>
> > as you rightly mentioned,cat /proc/kmsg is showing the time stamps,
> > according to that it is 0ms only.
> > But when you see the same with UART there is 2sec delay in showing the
> next
> > log. i caught this while i m observing the UART logs with
> > "Terminaliranicca".
>
> Oh, I could believe there's 2 seconds of time used up there that doesn't
> show in kernel timestamps because the timers aren't started yet.
>
> > Since i m early in the mm_init, i cant use watchdog to detect it,
> hrtimers
> > i cant use..i am really thinking how to analyse this delay..
>
> Time for some lateral thinking.. :)
>
> Can you give us some specs on the hardware (in particular, the CPU
> type/speed
> and how much RAM is installed)?  2 seconds on a 2Ghz CPU is about 4 billion
> cycles.
>
> Also, are you adding any code into the mm_init path? If so, what exactly
> are you doing?
>
> I wonder how early the kernel tracing and profiling stuff is enabled.  It
> may
> be possible to boot a kernel that has function-call tracing enabled, which
> would not have timing info, but if you see a function that's being called
> 500K
> times that should only be called a dozen times, that's probably your
> problem :)
> You'd probably want it with 'init=/bin/bash' and dump the stuff, as
> running to
> multiuser will almost certainly roll the buffers and lose the info).
>
>


-- 
With regards,
Sandeep Kumar Anantapalli,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130122/994b0755/attachment.html 

Can jiffies freeze?

[bill4carson]

On 2013?01?23? 03:32, sandeep kumar wrote:
>
> Hi Mr.Valdis
> as you rightly mentioned,cat /proc/kmsg is showing the time stamps, according to that it is 0ms only.
> But when you see the same with UART there is 2sec delay in showing the next log. i caught this while i m observing the UART logs with "Terminaliranicca".
>
Hmmm, all the boot messages are routed into a buffer it first printed into console, here there is no delay, possible tick timer are not setup yet.
But when it does get printed into the console, this process could be interrupted by other action as well, that's where you see a 2sec delay.

I hope I make myself clear:)





> Since i m early in the mm_init, i cant use watchdog to detect it, hrtimers i cant use..i am really thinking how to analyse this delay..
>
> Thanks
> Sandeep
>
> On Tue, Jan 22, 2013 at 10:40 AM, <Valdis.Kletnieks at vt.edu <mailto:Valdis.Kletnieks@vt.edu>> wrote:
>
>     On Tue, 22 Jan 2013 10:29:05 -0800, sandeep kumar said:
>
>      > I am seeing this problem at the very early in the start_kernel-->
>      > mm_init--> free_highpages, at that time nothing is up and kernel is running
>      > in single thread.
>
>     If you build a kernel with printk timestamps, you'll see that they all
>     come out like this:
>
>     [    0.000000] Initializing cgroup subsys cpuset
>     [    0.000000] Initializing cgroup subsys cpu
>     [    0.000000] Linux version 3.8.0-rc3-next-20130117-dirty (valdis at turing-police.cc.vt.edu <mailto:valdis@turing-police.cc.vt.edu>) (gcc version 4.7.2 20121109 (Red Hat 4.7.2-9) (GCC) ) #49 SMP PREEMPT Thu Jan 17 13:25:28 EST 2013
>     [    0.000000] Command line: ro root=/dev/mapper/vg_blackice-root log_buf_len=2M vga=893 loglevel=4 threadirqs intel_iommu=off LANG=en_US.UTF-8
>     [    0.000000] KERNEL supported cpus:
>     [    0.000000]   Intel GenuineIntel
>     [    0.000000] e820: BIOS-provided physical RAM map:
>     [    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009bbff] usable
>     [    0.000000] BIOS-e820: [mem 0x000000000009bc00-0x000000000009ffff] reserved
>     (100 or so more lines with same timestamp)
>     (now we finish memory init)
>     [    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes)
>     [    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes)
>     [    0.000000] __ex_table already sorted, skipping sort
>     [    0.000000] xsave: enabled xstate_bv 0x3, cntxt size 0x240
>     [    0.000000] Memory: 4015936k/4718592k available (6266k kernel code, 536744k absent, 165912k reserved, 7260k data, 576k init)
>     (more lines skipped)
>     [    0.000000]  memory used by lock dependency info: 5855 kB
>     [    0.000000]  per task-struct memory footprint: 1920 bytes
>     [    0.000000] hpet clockevent registered
>     [    0.000000] tsc: Fast TSC calibration using PIT
>     [    0.000000] tsc: Detected 2527.012 MHz processor
>     [    0.001004] Calibrating delay loop (skipped), value calculated using timer frequency.. 5054.02 BogoMIPS (lpj=2527012)
>     [    0.001009] pid_max: default: 32768 minimum: 301
>     [    0.001100] Security Framework initialized
>
>     It probably simply be that your code is running before the clock is started
>     by the kernel.
>
>
>
>
> --
> With regards,
> Sandeep Kumar Anantapalli,
>
>
>
> _______________________________________________
> Kernelnewbies mailing list
> Kernelnewbies at kernelnewbies.org
> http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies

-- 
?????????,??????????

--bill

Can jiffies freeze?

[Valdis.Kletnieks at vt.edu]

On Wed, 23 Jan 2013 14:05:25 +0800, bill4carson said:

> Hmmm, all the boot messages are routed into a buffer it first printed into
> console, here there is no delay, possible tick timer are not setup yet.
> But when it does get printed into the console, this process could be
> interrupted by other action as well, that's where you see a 2sec delay.

Unlikely, unless Sandeep is running an actual serial console at a very
low speed (which *can* cause fun on large NUMA machines that spew lots
of messages).  I'm pretty convinced that Sandeep is actually seeing a
2 second delay somewhere near mm_init that isn't reflected in the timestamps
because mm_init runs before the clocks are set up.

Of course, it may not be mm_init *itself* that's causing the delay - all
we *really* know is it's somewhere between a printk in mm_init and the
previous printk - there may be something *else* in between that's the
actual time sink.

Sandeep - I admit not having tried it, but can you see if booting with
'initcall_debug' narrows down where your problem is?  If the initcall
stuff is running early enough (I'm not sure when it starts relative to
mm_init), you'll get a message from each initcall as it is entered end
exited.  With any luck, that will help narrow down exactly where your
problem is.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 865 bytes
Desc: not available
Url : http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20130123/8d4797d4/attachment.bin