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,
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
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
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@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
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@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
_______________________________________________ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
-- With regards, Sandeep Kumar Anantapalli,
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@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
_______________________________________________ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
-- With regards, Sandeep Kumar Anantapalli,
-- With regards, Sandeep Kumar Anantapalli,
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
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@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.
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@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,
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).
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,
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@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@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@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
-- 八百里秦川尘土飞扬,三千万老陕齐吼秦腔。 --bill
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.
participants (6)
-
anish singh -
bill4carson -
hejianet -
Mulyadi Santosa -
sandeep kumar -
Valdis.Kletnieks＠vt.edu