Re: Can jiffies freeze?
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. pgpoTc5cSjbfb.pgp Description: PGP signature ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
On Wed, Jan 23, 2013 at 1:36 AM, sandeep kumar coolsandyfor...@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 ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
Hi.. On Tue, Jan 22, 2013 at 12:51 PM, sandeep kumar coolsandyfor...@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 ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
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
Re: Can jiffies freeze?
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 hejia...@linux.vnet.ibm.comwrote: 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, ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
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.00] Initializing cgroup subsys cpuset [0.00] Initializing cgroup subsys cpu [0.00] Linux version 3.8.0-rc3-next-20130117-dirty (val...@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.00] 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.00] KERNEL supported cpus: [0.00] Intel GenuineIntel [0.00] e820: BIOS-provided physical RAM map: [0.00] BIOS-e820: [mem 0x-0x0009bbff] usable [0.00] BIOS-e820: [mem 0x0009bc00-0x0009] reserved (100 or so more lines with same timestamp) (now we finish memory init) [0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes) [0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes) [0.00] __ex_table already sorted, skipping sort [0.00] xsave: enabled xstate_bv 0x3, cntxt size 0x240 [0.00] Memory: 4015936k/4718592k available (6266k kernel code, 536744k absent, 165912k reserved, 7260k data, 576k init) (more lines skipped) [0.00] memory used by lock dependency info: 5855 kB [0.00] per task-struct memory footprint: 1920 bytes [0.00] hpet clockevent registered [0.00] tsc: Fast TSC calibration using PIT [0.00] 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. pgpWqlU6S1t4c.pgp Description: PGP signature ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
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 coolsandyfor...@gmail.comwrote: 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 hejia...@linux.vnet.ibm.comwrote: 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, ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
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.kletni...@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.00] Initializing cgroup subsys cpuset [0.00] Initializing cgroup subsys cpu [0.00] Linux version 3.8.0-rc3-next-20130117-dirty ( val...@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.00] 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.00] KERNEL supported cpus: [0.00] Intel GenuineIntel [0.00] e820: BIOS-provided physical RAM map: [0.00] BIOS-e820: [mem 0x-0x0009bbff] usable [0.00] BIOS-e820: [mem 0x0009bc00-0x0009] reserved (100 or so more lines with same timestamp) (now we finish memory init) [0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes) [0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes) [0.00] __ex_table already sorted, skipping sort [0.00] xsave: enabled xstate_bv 0x3, cntxt size 0x240 [0.00] Memory: 4015936k/4718592k available (6266k kernel code, 536744k absent, 165912k reserved, 7260k data, 576k init) (more lines skipped) [0.00] memory used by lock dependency info: 5855 kB [0.00] per task-struct memory footprint: 1920 bytes [0.00] hpet clockevent registered [0.00] tsc: Fast TSC calibration using PIT [0.00] 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
Re: Can jiffies freeze?
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). pgpHTz8BL1r2i.pgp Description: PGP signature ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
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.kletni...@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, ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
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.kletni...@vt.edu mailto:valdis.kletni...@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.00] Initializing cgroup subsys cpuset [0.00] Initializing cgroup subsys cpu [0.00] Linux version 3.8.0-rc3-next-20130117-dirty (val...@turing-police.cc.vt.edu mailto:val...@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.00] 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.00] KERNEL supported cpus: [0.00] Intel GenuineIntel [0.00] e820: BIOS-provided physical RAM map: [0.00] BIOS-e820: [mem 0x-0x0009bbff] usable [0.00] BIOS-e820: [mem 0x0009bc00-0x0009] reserved (100 or so more lines with same timestamp) (now we finish memory init) [0.00] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes) [0.00] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes) [0.00] __ex_table already sorted, skipping sort [0.00] xsave: enabled xstate_bv 0x3, cntxt size 0x240 [0.00] Memory: 4015936k/4718592k available (6266k kernel code, 536744k absent, 165912k reserved, 7260k data, 576k init) (more lines skipped) [0.00] memory used by lock dependency info: 5855 kB [0.00] per task-struct memory footprint: 1920 bytes [0.00] hpet clockevent registered [0.00] tsc: Fast TSC calibration using PIT [0.00] 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 ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Can jiffies freeze?
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, ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
Re: Can jiffies freeze?
On Tue, Jan 22, 2013 at 11:21 AM, sandeep kumar coolsandyfor...@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 ___ Kernelnewbies mailing list Kernelnewbies@kernelnewbies.org http://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies
