* ath5k: kernel timing screwed - due to unserialised register access? @ 2008-10-05 21:45 Elias Oltmanns 2008-10-05 21:59 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-05 21:45 UTC (permalink / raw) To: Jiri Slaby, Thomas Gleixner; +Cc: linux-wireless Hi there, on my system, I observe some odd symptoms which I have troubled Thomas with before. After some more investigation, I have come to the conclusion that ath5k is at the bottom of this, but since I don't really understand the connection, I thought that Thomas may perhaps throw some light on the matter, after all, even though I still think that ath5k will have to be fixed. The Behaviour I'm seeing is this: sometimes, timers fire prematurely, i.e. a timer x started with mod_timer(&x, HZ/50); fires after less than 10 or even 1 msec rather than 20 msec. Trying to get to the bottom of this, it struck me that these glitches only occur when ath5k is loaded and an interface is brought up (ifconfig wlan0 up is quite sufficient). Some more digging revealed that the occurrences of such ``fast forward events'' coincided with the expiry of the recalibration timer started for the interface. The same behaviour can be observed on kernels 2.6.25.16, 2.6.26.5, 2.6.27-rc8-git8 and next-20080919. Looking through the code, I tried to find an obvious suspect, but nothing struck me as out of the ordinary, except for one thing: There doesn't seem to be anything in place that ensures serialisation of calls to the functions involved in calibration or, indeed, accesses to the card's registers. There definitely are parts of the calibration sequence that don't just get called from the calibration timer callback, so I think something has to be done about that. My first question is, can simultaneous unserialised accesses to registers possibly disturb softirqs in the way I see it happen, or do I have to look for something else? What about the locking issue? In fact, I wonder whether this really is the only place in the driver where we face the problem of potential concurrent access to the same registers including bit manipulations that require a read-write-in-a-row operation. Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-05 21:45 ath5k: kernel timing screwed - due to unserialised register access? Elias Oltmanns @ 2008-10-05 21:59 ` Thomas Gleixner 2008-10-06 14:04 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-05 21:59 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Sun, 5 Oct 2008, Elias Oltmanns wrote: > Hi there, > > on my system, I observe some odd symptoms which I have troubled Thomas > with before. After some more investigation, I have come to the > conclusion that ath5k is at the bottom of this, but since I don't really > understand the connection, I thought that Thomas may perhaps throw some > light on the matter, after all, even though I still think that ath5k > will have to be fixed. The Behaviour I'm seeing is this: sometimes, > timers fire prematurely, i.e. a timer x started with > > mod_timer(&x, HZ/50); > > fires after less than 10 or even 1 msec rather than 20 msec. Trying to > get to the bottom of this, it struck me that these glitches only occur > when ath5k is loaded and an interface is brought up (ifconfig wlan0 up > is quite sufficient). Some more digging revealed that the occurrences of > such ``fast forward events'' coincided with the expiry of the > recalibration timer started for the interface. The same behaviour can be > observed on kernels 2.6.25.16, 2.6.26.5, 2.6.27-rc8-git8 and > next-20080919. We had an intermittent problem with jffies based timers between 2.6.27-rc6 and -rc8-latest. This is fixed in current mainline. It only happened when CONFIG_NOHZ=n and CONFIG_HIGH_RES_TIMERS=n or both options were disabled at the kernel commandline. I have no idea why this should happen on any other kernel versions. Can you please point me to the code in question (file, line number) ? Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-05 21:59 ` Thomas Gleixner @ 2008-10-06 14:04 ` Elias Oltmanns 2008-10-06 19:47 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-06 14:04 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless [-- Attachment #1: Type: text/plain, Size: 2890 bytes --] Thomas Gleixner <tglx@linutronix.de> wrote: > On Sun, 5 Oct 2008, Elias Oltmanns wrote: >> Hi there, > >> >> on my system, I observe some odd symptoms which I have troubled Thomas >> with before. After some more investigation, I have come to the >> conclusion that ath5k is at the bottom of this, but since I don't really >> understand the connection, I thought that Thomas may perhaps throw some >> light on the matter, after all, even though I still think that ath5k >> will have to be fixed. The Behaviour I'm seeing is this: sometimes, >> timers fire prematurely, i.e. a timer x started with >> >> mod_timer(&x, HZ/50); >> >> fires after less than 10 or even 1 msec rather than 20 msec. Trying to >> get to the bottom of this, it struck me that these glitches only occur >> when ath5k is loaded and an interface is brought up (ifconfig wlan0 up >> is quite sufficient). Some more digging revealed that the occurrences of >> such ``fast forward events'' coincided with the expiry of the >> recalibration timer started for the interface. The same behaviour can be >> observed on kernels 2.6.25.16, 2.6.26.5, 2.6.27-rc8-git8 and >> next-20080919. > > We had an intermittent problem with jffies based timers between > 2.6.27-rc6 and -rc8-latest. This is fixed in current mainline. It only > happened when CONFIG_NOHZ=n and CONFIG_HIGH_RES_TIMERS=n or both > options were disabled at the kernel commandline. No, it isn't that one. My problem can be reproduced most reliably when NO_HZ is enabled (HIGH_RES_TIMERS doesn't seem to matter). > > I have no idea why this should happen on any other kernel versions. > > Can you please point me to the code in question (file, line number) ? Well, I'm suspicious about ath5k_calibrate() (defined in drivers/net/wireless/ath5k/base.c) and everything that gets called from there, to begin with. This is the timer callback function and is executed every ten seconds by default. Perhaps you'd like to start by looking at ath5k_hw_noise_floor_calibration() in drivers/net/wireless/ath5k/phy.c. This function is called as part of the calibration sequence performed by ath5k_calibrate() in softirq context. Additionally, it is part of the reset sequence which can be initiated from various place in both, process and softirq context (look for calls to ath5k_reset() in drivers/net/wireless/ath5k/base.c). Also, here is some information about my test case: Please find below a patch to Linus' tree which adds a simple test module. Secondly, I've attached the source of the simple program chktimer. After rebooting into the new kernel, I do the following to verify that the problem is still present: # modprobe evdev # modprobe timer-test # modprobe ath5k # ifconfig wlan0 up # chktimer /dev/input/event1 Make sure that event1 is the right device. chktimer usually reports several premature timer expiries in less than a minute. Regards, Elias [-- Warning: decoded text below may be mangled, UTF-8 assumed --] [-- Attachment #2: timer-test.patch --] [-- Type: text/x-diff; name=timer-test.patch, Size: 3216 bytes --] drivers/misc/Kconfig | 11 ++++++ drivers/misc/Makefile | 1 + drivers/misc/timer-test.c | 80 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 92 insertions(+), 0 deletions(-) create mode 100644 drivers/misc/timer-test.c diff --git a/drivers/misc/Kconfig b/drivers/misc/Kconfig index a726f3b..7ebdcfc 100644 --- a/drivers/misc/Kconfig +++ b/drivers/misc/Kconfig @@ -475,4 +475,15 @@ config SGI_GRU_DEBUG This option enables addition debugging code for the SGI GRU driver. If you are unsure, say N. +config TIMER_TEST + tristate "timer stress test" + default n + select INPUT + ---help--- + This is some code for stress testing the timer code. It is purely for + debugging purposes and should generally be disabled. If built as a + module, the module will be called timer-test. + + If you are unsure, say N. + endif # MISC_DEVICES diff --git a/drivers/misc/Makefile b/drivers/misc/Makefile index c6c13f6..ffffd78 100644 --- a/drivers/misc/Makefile +++ b/drivers/misc/Makefile @@ -30,3 +30,4 @@ obj-$(CONFIG_KGDB_TESTS) += kgdbts.o obj-$(CONFIG_SGI_XP) += sgi-xp/ obj-$(CONFIG_SGI_GRU) += sgi-gru/ obj-$(CONFIG_HP_ILO) += hpilo.o +obj-$(CONFIG_TIMER_TEST) += timer-test.o diff --git a/drivers/misc/timer-test.c b/drivers/misc/timer-test.c new file mode 100644 index 0000000..a58adcf --- /dev/null +++ b/drivers/misc/timer-test.c @@ -0,0 +1,80 @@ +#include <linux/input.h> +#include <linux/kernel.h> +#include <linux/module.h> +#include <linux/timer.h> +#include <linux/jiffies.h> +#include <linux/delay.h> + +#define TSTM_FREQ 50 + +static struct timer_list tstm_timer; +static struct input_dev *tstm_idev; +static int key_state = 0; + +static void tstm_input_update(unsigned long data) +{ + key_state ^= 1; + input_report_key(tstm_idev, BTN_0, key_state); + input_sync(tstm_idev); + mod_timer(&tstm_timer, jiffies + HZ/TSTM_FREQ); +} + +static int tstm_dev_open(struct input_dev *dev) +{ + mod_timer(&tstm_timer, jiffies + HZ/TSTM_FREQ); + return 0; +} + +static void tstm_dev_close(struct input_dev *dev) +{ + del_timer_sync(&tstm_timer); +} + +static int __init tstm_init(void) +{ + int ret; + + tstm_idev = input_allocate_device(); + if (!tstm_idev) { + ret = -ENOMEM; + goto out; + } + + /* initialise the input device */ + tstm_idev->name = "Timer stress test data"; + tstm_idev->phys = "tstm/input0"; + tstm_idev->id.bustype = BUS_HOST; + tstm_idev->evbit[0] = BIT(EV_KEY); + tstm_idev->keybit[BIT_WORD(BTN_0)] = BIT_MASK(BTN_0); + tstm_idev->open = tstm_dev_open; + tstm_idev->close = tstm_dev_close; + + ret = input_register_device(tstm_idev); + if (ret) + goto out_idev; + + init_timer(&tstm_timer); + tstm_timer.function = tstm_input_update; + + printk(KERN_INFO "timer-test: module successfully loaded.\n"); + return 0; + +out_idev: + input_free_device(tstm_idev); +out: + printk(KERN_WARNING "timer-test: module init failed (ret=%d)!\n", ret); + return ret; +} + +static void __exit tstm_exit(void) +{ + input_unregister_device(tstm_idev); + printk(KERN_INFO "tstm: module unloaded.\n"); +} + +module_init(tstm_init); +module_exit(tstm_exit); + +MODULE_AUTHOR("Elias Oltmanns"); +MODULE_DESCRIPTION("Timer stress test module"); +MODULE_LICENSE("GPL v2"); [-- Warning: decoded text below may be mangled, UTF-8 assumed --] [-- Attachment #3: chktimer.c --] [-- Type: text/x-csrc; name=chktimer.c, Size: 799 bytes --] #include <stdio.h> #include <unistd.h> #include <fcntl.h> #include <sys/time.h> #include <errno.h> #include <linux/input.h> int main(int argc, char *argv[]) { struct input_event ev; double unow = 0, old_unow = 0; int fd; if (argc != 2) { printf("Usage: %s <inputdev>\n", argv[0]); return 1; } fd = open(argv[1], O_RDONLY); if (fd < 0) { printf("Cannot open %s.\n", argv[1]); return 2; } while (read(fd, &ev, sizeof(struct input_event)) == sizeof(struct input_event)) { if (ev.type != EV_SYN) continue; unow = ev.time.tv_sec + ev.time.tv_usec/1000000.0; if (unow - old_unow < 0.001) { struct timeval tm; gettimeofday(&tm, NULL); printf("[%5lu.%06lu] Premature timer expiry.\n", tm.tv_sec, tm.tv_usec); } old_unow = unow; } return 0; } ^ permalink raw reply related [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-06 14:04 ` Elias Oltmanns @ 2008-10-06 19:47 ` Thomas Gleixner 2008-10-07 15:27 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-06 19:47 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Mon, 6 Oct 2008, Elias Oltmanns wrote: > Make sure that event1 is the right device. chktimer usually reports > several premature timer expiries in less than a minute. Which is not surprising. You measure the delta of the reads. Your process can be scheduled away and when it comes back two events can be available, so they are read right after each other and trigger your check. Your measuring method is wrong. You really want to measure the delta of the timer events in the kernel via ktime_get(), not the delta of something else in userspace. Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-06 19:47 ` Thomas Gleixner @ 2008-10-07 15:27 ` Elias Oltmanns 2008-10-07 18:02 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-07 15:27 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Mon, 6 Oct 2008, Elias Oltmanns wrote: >> Make sure that event1 is the right device. chktimer usually reports >> several premature timer expiries in less than a minute. [...] > Your measuring method is wrong. You really want to measure the delta > of the timer events in the kernel via ktime_get(), not the delta of > something else in userspace. Alright, here is a stripped down version of the test case. This time, you only need to load the timer-test module and start up the ath5k interface. The glitch is triggered slightly less reliably, but I can still easily verify that the problem is present when running 2.6.27-rc9 on my system. Regards, Elias --- drivers/misc/Kconfig | 11 ++++++++++ drivers/misc/Makefile | 1 + drivers/misc/timer-test.c | 50 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 62 insertions(+), 0 deletions(-) create mode 100644 drivers/misc/timer-test.c diff --git a/drivers/misc/Kconfig b/drivers/misc/Kconfig index a726f3b..7ebdcfc 100644 --- a/drivers/misc/Kconfig +++ b/drivers/misc/Kconfig @@ -475,4 +475,15 @@ config SGI_GRU_DEBUG This option enables addition debugging code for the SGI GRU driver. If you are unsure, say N. +config TIMER_TEST + tristate "timer stress test" + default n + select INPUT + ---help--- + This is some code for stress testing the timer code. It is purely for + debugging purposes and should generally be disabled. If built as a + module, the module will be called timer-test. + + If you are unsure, say N. + endif # MISC_DEVICES diff --git a/drivers/misc/Makefile b/drivers/misc/Makefile index c6c13f6..ffffd78 100644 --- a/drivers/misc/Makefile +++ b/drivers/misc/Makefile @@ -30,3 +30,4 @@ obj-$(CONFIG_KGDB_TESTS) += kgdbts.o obj-$(CONFIG_SGI_XP) += sgi-xp/ obj-$(CONFIG_SGI_GRU) += sgi-gru/ obj-$(CONFIG_HP_ILO) += hpilo.o +obj-$(CONFIG_TIMER_TEST) += timer-test.o diff --git a/drivers/misc/timer-test.c b/drivers/misc/timer-test.c new file mode 100644 index 0000000..780f3dd --- /dev/null +++ b/drivers/misc/timer-test.c @@ -0,0 +1,50 @@ +#include <linux/kernel.h> +#include <linux/module.h> +#include <linux/timer.h> +#include <linux/jiffies.h> + +#define TSTM_FREQ 50 +#define __TSTM_THRESH (NSEC_PER_SEC / TSTM_FREQ / 20) +#if __TSTM_THRESH > 0 +# define TSTM_THRESH __TSTM_THRESH +#else +# define TSTM_THRESH 1 +#endif + +static struct timer_list tstm_timer; + +static void tstm_callback(unsigned long data) +{ + static struct timespec before; + struct timespec now, diff; + + ktime_get_ts(&now); + diff = timespec_sub(now, before); + if (timespec_to_ns(&diff) < TSTM_THRESH) + printk(KERN_INFO "Timer expired prematurely.\n"); + before = now; + mod_timer(&tstm_timer, jiffies + HZ/TSTM_FREQ); +} + +static int __init tstm_init(void) +{ + init_timer(&tstm_timer); + tstm_timer.function = tstm_callback; + mod_timer(&tstm_timer, jiffies + HZ/TSTM_FREQ); + + printk(KERN_INFO "timer-test: module successfully loaded.\n"); + return 0; +} + +static void __exit tstm_exit(void) +{ + del_timer_sync(&tstm_timer); + printk(KERN_INFO "tstm: module unloaded.\n"); +} + +module_init(tstm_init); +module_exit(tstm_exit); + +MODULE_AUTHOR("Elias Oltmanns"); +MODULE_DESCRIPTION("Timer stress test module"); +MODULE_LICENSE("GPL v2"); ^ permalink raw reply related [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-07 15:27 ` Elias Oltmanns @ 2008-10-07 18:02 ` Thomas Gleixner 2008-10-07 18:44 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-07 18:02 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Tue, 7 Oct 2008, Elias Oltmanns wrote: > Thomas Gleixner <tglx@linutronix.de> wrote: > > On Mon, 6 Oct 2008, Elias Oltmanns wrote: > >> Make sure that event1 is the right device. chktimer usually reports > >> several premature timer expiries in less than a minute. > [...] > > Your measuring method is wrong. You really want to measure the delta > > of the timer events in the kernel via ktime_get(), not the delta of > > something else in userspace. > > Alright, here is a stripped down version of the test case. This time, > you only need to load the timer-test module and start up the ath5k > interface. The glitch is triggered slightly less reliably, but I can -ENOATH5KHARDWARE > still easily verify that the problem is present when running 2.6.27-rc9 > on my system. Hmm. Can you please add some real info to the printk :) > + if (timespec_to_ns(&diff) < TSTM_THRESH) > + printk(KERN_INFO "Timer expired prematurely.\n"); e.g.: printk(KERN_INFO "b: %6ld.%09ld n: %6ld.09ld e: %lu j: %lu\n", before.tv_sec, before.tv_nsec, now.tv_sec, now.tv_nsec, tstm_timer.expires, jiffies); Does this happen w/o the ath5k driver as well ? Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-07 18:02 ` Thomas Gleixner @ 2008-10-07 18:44 ` Thomas Gleixner 2008-10-07 21:23 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-07 18:44 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Tue, 7 Oct 2008, Thomas Gleixner wrote: > On Tue, 7 Oct 2008, Elias Oltmanns wrote: > > Thomas Gleixner <tglx@linutronix.de> wrote: > > > On Mon, 6 Oct 2008, Elias Oltmanns wrote: > > >> Make sure that event1 is the right device. chktimer usually reports > > >> several premature timer expiries in less than a minute. > > [...] > > > Your measuring method is wrong. You really want to measure the delta > > > of the timer events in the kernel via ktime_get(), not the delta of > > > something else in userspace. > > > > Alright, here is a stripped down version of the test case. This time, > > you only need to load the timer-test module and start up the ath5k > > interface. The glitch is triggered slightly less reliably, but I can > > -ENOATH5KHARDWARE > > > still easily verify that the problem is present when running 2.6.27-rc9 > > on my system. > > Hmm. Can you please add some real info to the printk :) > > > + if (timespec_to_ns(&diff) < TSTM_THRESH) > > + printk(KERN_INFO "Timer expired prematurely.\n"); > > e.g.: > > printk(KERN_INFO "b: %6ld.%09ld n: %6ld.09ld e: %lu j: %lu\n", > before.tv_sec, before.tv_nsec, now.tv_sec, now.tv_nsec, > tstm_timer.expires, jiffies); > > Does this happen w/o the ath5k driver as well ? Some more questions: Does this happen with any on the combinations of highres/nohz enabled/disabled ? Can you please add: sysrq_timer_list_show(); after the printk. You have to export it in kernel/time/timer_list.c to use it with a module Please do cat /proc/timer_list right before you start the module as well. Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-07 18:44 ` Thomas Gleixner @ 2008-10-07 21:23 ` Elias Oltmanns 2008-10-08 11:39 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-07 21:23 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Tue, 7 Oct 2008, Thomas Gleixner wrote: >> On Tue, 7 Oct 2008, Elias Oltmanns wrote: > >> > Thomas Gleixner <tglx@linutronix.de> wrote: >> > > On Mon, 6 Oct 2008, Elias Oltmanns wrote: >> > >> Make sure that event1 is the right device. chktimer usually reports >> > >> several premature timer expiries in less than a minute. >> > [...] >> > > Your measuring method is wrong. You really want to measure the delta >> > > of the timer events in the kernel via ktime_get(), not the delta of >> > > something else in userspace. >> > >> > Alright, here is a stripped down version of the test case. This time, >> > you only need to load the timer-test module and start up the ath5k >> > interface. The glitch is triggered slightly less reliably, but I can >> >> -ENOATH5KHARDWARE Well, that's why I posted this on linux-wireless in the first place. In fact, I just *hoped* for some general advice from you in the matter especially regarding the question whether concurrent accesses to pci card registers might possibly cause such a behaviour or whether I'd have to look for something else. Obviously, I'm very happy that you take such an interest in this affair even though it seems to be very closely related to a particular device driver. >> >> > still easily verify that the problem is present when running 2.6.27-rc9 >> > on my system. >> >> Hmm. Can you please add some real info to the printk :) >> >> > + if (timespec_to_ns(&diff) < TSTM_THRESH) >> > + printk(KERN_INFO "Timer expired prematurely.\n"); >> >> e.g.: >> >> printk(KERN_INFO "b: %6ld.%09ld n: %6ld.09ld e: %lu j: %lu\n", >> before.tv_sec, before.tv_nsec, now.tv_sec, now.tv_nsec, >> tstm_timer.expires, jiffies); >> >> Does this happen w/o the ath5k driver as well ? At least, I don't recall seeing this when the interface was down or even the driver unloaded. > > Some more questions: > > Does this happen with any on the combinations of highres/nohz > enabled/disabled ? >From my tests in the past it would appear that NO_HZ enabled is the most important option to trigger the problem speedily. HIGHRES_TIMERS didn't seem to make much difference and I am quite sure that I observed this issue with NO_HZ disabled too, but very rarely. I'll keep testing and reporting. Meanwhile, ... > > Can you please add: > > sysrq_timer_list_show(); > > after the printk. You have to export it in kernel/time/timer_list.c > to use it with a module > > Please do cat /proc/timer_list right before you start the module as well. ... here are some results for CONFIG_NO_HZ=y # CONFIG_HIGH_RES_TIMERS is not set --8<---------------/proc/timer_list---------------start------------->8--- Timer List Version: v0.3 HRTIMER_MAX_CLOCK_BASES: 2 now at 176358191709 nsecs cpu: 0 clock 0: .index: 0 .resolution: 10000000 nsecs .get_time: ktime_get_real active timers: clock 1: .index: 1 .resolution: 10000000 nsecs .get_time: ktime_get active timers: #0: <de135ec0>, it_real_fn, S:01, do_setitimer, syslogd/2446 # expires at 203020070149 nsecs [in 26661878440 nsecs] .nohz_mode : 1 .idle_tick : 176330000000 nsecs .tick_stopped : 0 .idle_jiffies : 4294954928 .idle_calls : 23924 .idle_sleeps : 20168 .idle_entrytime : 176347614104 nsecs .idle_waketime : 176355789447 nsecs .idle_exittime : 176355831632 nsecs .idle_sleeptime : 164535951430 nsecs .last_jiffies : 4294954930 .next_jiffies : 4294954933 .idle_expires : 176370000000 nsecs jiffies: 4294954931 Tick Device: mode: 1 Clock Event Device: pit max_delta_ns: 27461866 min_delta_ns: 12571 mult: 5124677 shift: 32 mode: 3 next_event: 176370000000 nsecs set_next_event: pit_next_event set_mode: init_pit_timer event_handler: tick_handle_oneshot_broadcast tick_broadcast_mask: 00000001 tick_broadcast_oneshot_mask: 00000000 Tick Device: mode: 1 Clock Event Device: lapic max_delta_ns: 1346509690 min_delta_ns: 2407 mult: 26757173 shift: 32 mode: 3 next_event: 176360000000 nsecs set_next_event: lapic_next_event set_mode: lapic_timer_setup event_handler: tick_nohz_handler --8<---------------/proc/timer_list---------------end--------------->8--- --8<---------------dmesg---------------start------------->8--- Oct 7 22:16:06 denkblock kernel: [ 182.852847] timer-test: module successfully loaded. Oct 7 22:16:13 denkblock kernel: [ 190.406715] NET: Registered protocol family 17 [ ath0 start up and associate with AP ] Oct 7 22:16:43 denkblock kernel: [ 220.061949] b: 220.061926318 n: 220.061943080 e: 4294959302 j: 4294959302 Oct 7 22:16:43 denkblock kernel: [ 220.061957] Timer List Version: v0.3 Oct 7 22:16:43 denkblock kernel: [ 220.061960] HRTIMER_MAX_CLOCK_BASES: 2 Oct 7 22:16:43 denkblock kernel: [ 220.061963] now at 220061956490 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.061965] Oct 7 22:16:43 denkblock kernel: [ 220.061967] cpu: 0 Oct 7 22:16:43 denkblock kernel: [ 220.061970] clock 0: Oct 7 22:16:43 denkblock kernel: [ 220.061972] .index: 0 Oct 7 22:16:43 denkblock kernel: [ 220.061974] .resolution: 10000000 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.061977] .get_time: ktime_get_real Oct 7 22:16:43 denkblock kernel: [ 220.061987] active timers: Oct 7 22:16:43 denkblock kernel: [ 220.061990] clock 1: Oct 7 22:16:43 denkblock kernel: [ 220.061992] .index: 1 Oct 7 22:16:43 denkblock kernel: [ 220.061995] .resolution: 10000000 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.061997] .get_time: ktime_get Oct 7 22:16:43 denkblock kernel: [ 220.062002] active timers: Oct 7 22:16:43 denkblock kernel: [ 220.062005] #0: softirq_stack, hrtimer_wakeup, S:01, do_nanosleep, tail/2677 Oct 7 22:16:43 denkblock kernel: [ 220.062024] # expires at 221010411656 nsecs [in 948455166 nsecs] Oct 7 22:16:43 denkblock kernel: [ 220.062028] #1: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2446 Oct 7 22:16:43 denkblock kernel: [ 220.062041] # expires at 233030065277 nsecs [in 12968108787 nsecs] Oct 7 22:16:43 denkblock kernel: [ 220.062046] .nohz_mode : 1 Oct 7 22:16:43 denkblock kernel: [ 220.062049] .idle_tick : 219990000000 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062052] .tick_stopped : 0 Oct 7 22:16:43 denkblock kernel: [ 220.062055] .idle_jiffies : 4294959296 Oct 7 22:16:43 denkblock kernel: [ 220.062058] .idle_calls : 30373 Oct 7 22:16:43 denkblock kernel: [ 220.062060] .idle_sleeps : 24439 Oct 7 22:16:43 denkblock kernel: [ 220.062063] .idle_entrytime : 220030129810 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062066] .idle_waketime : 220010010209 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062070] .idle_exittime : 220010028367 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062073] .idle_sleeptime : 204917963234 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062076] .last_jiffies : 4294959299 Oct 7 22:16:43 denkblock kernel: [ 220.062079] .next_jiffies : 4294959300 Oct 7 22:16:43 denkblock kernel: [ 220.062082] .idle_expires : 220010000000 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062085] jiffies: 4294959302 Oct 7 22:16:43 denkblock kernel: [ 220.062087] Oct 7 22:16:43 denkblock kernel: [ 220.062089] Oct 7 22:16:43 denkblock kernel: [ 220.062091] Tick Device: mode: 1 Oct 7 22:16:43 denkblock kernel: [ 220.062093] Clock Event Device: pit Oct 7 22:16:43 denkblock kernel: [ 220.062097] max_delta_ns: 27461866 Oct 7 22:16:43 denkblock kernel: [ 220.062100] min_delta_ns: 12571 Oct 7 22:16:43 denkblock kernel: [ 220.062103] mult: 5124677 Oct 7 22:16:43 denkblock kernel: [ 220.062105] shift: 32 Oct 7 22:16:43 denkblock kernel: [ 220.062108] mode: 3 Oct 7 22:16:43 denkblock kernel: [ 220.062111] next_event: 9223372036854775807 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062114] set_next_event: pit_next_event Oct 7 22:16:43 denkblock kernel: [ 220.062121] set_mode: init_pit_timer Oct 7 22:16:43 denkblock kernel: [ 220.062126] event_handler: tick_handle_oneshot_broadcast Oct 7 22:16:43 denkblock kernel: [ 220.062134] tick_broadcast_mask: 00000001 Oct 7 22:16:43 denkblock kernel: [ 220.062137] tick_broadcast_oneshot_mask: 00000000 Oct 7 22:16:43 denkblock kernel: [ 220.062139] Oct 7 22:16:43 denkblock kernel: [ 220.062141] Oct 7 22:16:43 denkblock kernel: [ 220.062143] Tick Device: mode: 1 Oct 7 22:16:43 denkblock kernel: [ 220.062145] Clock Event Device: lapic Oct 7 22:16:43 denkblock kernel: [ 220.062149] max_delta_ns: 1346509690 Oct 7 22:16:43 denkblock kernel: [ 220.062152] min_delta_ns: 2407 Oct 7 22:16:43 denkblock kernel: [ 220.062154] mult: 26757173 Oct 7 22:16:43 denkblock kernel: [ 220.062157] shift: 32 Oct 7 22:16:43 denkblock kernel: [ 220.062159] mode: 3 Oct 7 22:16:43 denkblock kernel: [ 220.062162] next_event: 220070000000 nsecs Oct 7 22:16:43 denkblock kernel: [ 220.062165] set_next_event: lapic_next_event Oct 7 22:16:43 denkblock kernel: [ 220.062171] set_mode: lapic_timer_setup Oct 7 22:16:43 denkblock kernel: [ 220.062175] event_handler: tick_nohz_handler Oct 7 22:16:43 denkblock kernel: [ 220.062181] Oct 7 22:16:53 denkblock kernel: [ 230.062974] b: 230.062949074 n: 230.062967513 e: 4294960302 j: 4294960302 Oct 7 22:16:53 denkblock kernel: [ 230.062981] Timer List Version: v0.3 Oct 7 22:16:53 denkblock kernel: [ 230.062984] HRTIMER_MAX_CLOCK_BASES: 2 Oct 7 22:16:53 denkblock kernel: [ 230.062987] now at 230062981201 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.062990] Oct 7 22:16:53 denkblock kernel: [ 230.062992] cpu: 0 Oct 7 22:16:53 denkblock kernel: [ 230.062994] clock 0: Oct 7 22:16:53 denkblock kernel: [ 230.062997] .index: 0 Oct 7 22:16:53 denkblock kernel: [ 230.062999] .resolution: 10000000 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063002] .get_time: ktime_get_real Oct 7 22:16:53 denkblock kernel: [ 230.063012] active timers: Oct 7 22:16:53 denkblock kernel: [ 230.063015] clock 1: Oct 7 22:16:53 denkblock kernel: [ 230.063017] .index: 1 Oct 7 22:16:53 denkblock kernel: [ 230.063019] .resolution: 10000000 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063022] .get_time: ktime_get Oct 7 22:16:53 denkblock kernel: [ 230.063027] active timers: Oct 7 22:16:53 denkblock kernel: [ 230.063030] #0: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2446 Oct 7 22:16:53 denkblock kernel: [ 230.063047] # expires at 233030065277 nsecs [in 2967084076 nsecs] Oct 7 22:16:53 denkblock kernel: [ 230.063051] .nohz_mode : 1 Oct 7 22:16:53 denkblock kernel: [ 230.063054] .idle_tick : 229990000000 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063057] .tick_stopped : 0 Oct 7 22:16:53 denkblock kernel: [ 230.063060] .idle_jiffies : 4294960294 Oct 7 22:16:53 denkblock kernel: [ 230.063063] .idle_calls : 31886 Oct 7 22:16:53 denkblock kernel: [ 230.063065] .idle_sleeps : 25474 Oct 7 22:16:53 denkblock kernel: [ 230.063068] .idle_entrytime : 230038292861 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063072] .idle_waketime : 229995775993 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063075] .idle_exittime : 229995796387 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063078] .idle_sleeptime : 214780228661 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063081] .last_jiffies : 4294960299 Oct 7 22:16:53 denkblock kernel: [ 230.063084] .next_jiffies : 4294960300 Oct 7 22:16:53 denkblock kernel: [ 230.063087] .idle_expires : 230000000000 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063090] jiffies: 4294960302 Oct 7 22:16:53 denkblock kernel: [ 230.063092] Oct 7 22:16:53 denkblock kernel: [ 230.063094] Oct 7 22:16:53 denkblock kernel: [ 230.063096] Tick Device: mode: 1 Oct 7 22:16:53 denkblock kernel: [ 230.063099] Clock Event Device: pit Oct 7 22:16:53 denkblock kernel: [ 230.063102] max_delta_ns: 27461866 Oct 7 22:16:53 denkblock kernel: [ 230.063105] min_delta_ns: 12571 Oct 7 22:16:53 denkblock kernel: [ 230.063108] mult: 5124677 Oct 7 22:16:53 denkblock kernel: [ 230.063111] shift: 32 Oct 7 22:16:53 denkblock kernel: [ 230.063113] mode: 3 Oct 7 22:16:53 denkblock kernel: [ 230.063116] next_event: 9223372036854775807 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063119] set_next_event: pit_next_event Oct 7 22:16:53 denkblock kernel: [ 230.063126] set_mode: init_pit_timer Oct 7 22:16:53 denkblock kernel: [ 230.063132] event_handler: tick_handle_oneshot_broadcast Oct 7 22:16:53 denkblock kernel: [ 230.063139] tick_broadcast_mask: 00000001 Oct 7 22:16:53 denkblock kernel: [ 230.063142] tick_broadcast_oneshot_mask: 00000000 Oct 7 22:16:53 denkblock kernel: [ 230.063145] Oct 7 22:16:53 denkblock kernel: [ 230.063146] Oct 7 22:16:53 denkblock kernel: [ 230.063148] Tick Device: mode: 1 Oct 7 22:16:53 denkblock kernel: [ 230.063151] Clock Event Device: lapic Oct 7 22:16:53 denkblock kernel: [ 230.063154] max_delta_ns: 1346509690 Oct 7 22:16:53 denkblock kernel: [ 230.063157] min_delta_ns: 2407 Oct 7 22:16:53 denkblock kernel: [ 230.063160] mult: 26757173 Oct 7 22:16:53 denkblock kernel: [ 230.063162] shift: 32 Oct 7 22:16:53 denkblock kernel: [ 230.063165] mode: 3 Oct 7 22:16:53 denkblock kernel: [ 230.063168] next_event: 230070000000 nsecs Oct 7 22:16:53 denkblock kernel: [ 230.063170] set_next_event: lapic_next_event Oct 7 22:16:53 denkblock kernel: [ 230.063176] set_mode: lapic_timer_setup Oct 7 22:16:53 denkblock kernel: [ 230.063181] event_handler: tick_nohz_handler Oct 7 22:16:53 denkblock kernel: [ 230.063186] Oct 7 22:17:03 denkblock kernel: [ 240.061943] b: 240.061920172 n: 240.061936655 e: 4294961302 j: 4294961302 Oct 7 22:17:03 denkblock kernel: [ 240.061950] Timer List Version: v0.3 Oct 7 22:17:03 denkblock kernel: [ 240.061953] HRTIMER_MAX_CLOCK_BASES: 2 Oct 7 22:17:03 denkblock kernel: [ 240.061956] now at 240061949785 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.061959] Oct 7 22:17:03 denkblock kernel: [ 240.061961] cpu: 0 Oct 7 22:17:03 denkblock kernel: [ 240.061963] clock 0: Oct 7 22:17:03 denkblock kernel: [ 240.061965] .index: 0 Oct 7 22:17:03 denkblock kernel: [ 240.061968] .resolution: 10000000 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.061971] .get_time: ktime_get_real Oct 7 22:17:03 denkblock kernel: [ 240.061981] active timers: Oct 7 22:17:03 denkblock kernel: [ 240.061984] clock 1: Oct 7 22:17:03 denkblock kernel: [ 240.061986] .index: 1 Oct 7 22:17:03 denkblock kernel: [ 240.061988] .resolution: 10000000 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.061991] .get_time: ktime_get Oct 7 22:17:03 denkblock kernel: [ 240.061996] active timers: Oct 7 22:17:03 denkblock kernel: [ 240.061999] #0: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2446 Oct 7 22:17:03 denkblock kernel: [ 240.062016] # expires at 263040078005 nsecs [in 22978128220 nsecs] Oct 7 22:17:03 denkblock kernel: [ 240.062020] .nohz_mode : 1 Oct 7 22:17:03 denkblock kernel: [ 240.062023] .idle_tick : 239990000000 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062026] .tick_stopped : 0 Oct 7 22:17:03 denkblock kernel: [ 240.062029] .idle_jiffies : 4294961296 Oct 7 22:17:03 denkblock kernel: [ 240.062032] .idle_calls : 33434 Oct 7 22:17:03 denkblock kernel: [ 240.062035] .idle_sleeps : 26515 Oct 7 22:17:03 denkblock kernel: [ 240.062037] .idle_entrytime : 240034626193 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062041] .idle_waketime : 240010010209 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062044] .idle_exittime : 240010025853 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062047] .idle_sleeptime : 224654904871 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062050] .last_jiffies : 4294961299 Oct 7 22:17:03 denkblock kernel: [ 240.062053] .next_jiffies : 4294961300 Oct 7 22:17:03 denkblock kernel: [ 240.062056] .idle_expires : 240010000000 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062059] jiffies: 4294961302 Oct 7 22:17:03 denkblock kernel: [ 240.062061] Oct 7 22:17:03 denkblock kernel: [ 240.062063] Oct 7 22:17:03 denkblock kernel: [ 240.062065] Tick Device: mode: 1 Oct 7 22:17:03 denkblock kernel: [ 240.062068] Clock Event Device: pit Oct 7 22:17:03 denkblock kernel: [ 240.062072] max_delta_ns: 27461866 Oct 7 22:17:03 denkblock kernel: [ 240.062074] min_delta_ns: 12571 Oct 7 22:17:03 denkblock kernel: [ 240.062077] mult: 5124677 Oct 7 22:17:03 denkblock kernel: [ 240.062080] shift: 32 Oct 7 22:17:03 denkblock kernel: [ 240.062082] mode: 3 Oct 7 22:17:03 denkblock kernel: [ 240.062085] next_event: 9223372036854775807 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062088] set_next_event: pit_next_event Oct 7 22:17:03 denkblock kernel: [ 240.062096] set_mode: init_pit_timer Oct 7 22:17:03 denkblock kernel: [ 240.062101] event_handler: tick_handle_oneshot_broadcast Oct 7 22:17:03 denkblock kernel: [ 240.062108] tick_broadcast_mask: 00000001 Oct 7 22:17:03 denkblock kernel: [ 240.062111] tick_broadcast_oneshot_mask: 00000000 Oct 7 22:17:03 denkblock kernel: [ 240.062114] Oct 7 22:17:03 denkblock kernel: [ 240.062115] Oct 7 22:17:03 denkblock kernel: [ 240.062117] Tick Device: mode: 1 Oct 7 22:17:03 denkblock kernel: [ 240.062120] Clock Event Device: lapic Oct 7 22:17:03 denkblock kernel: [ 240.062123] max_delta_ns: 1346509690 Oct 7 22:17:03 denkblock kernel: [ 240.062126] min_delta_ns: 2407 Oct 7 22:17:03 denkblock kernel: [ 240.062129] mult: 26757173 Oct 7 22:17:03 denkblock kernel: [ 240.062131] shift: 32 Oct 7 22:17:03 denkblock kernel: [ 240.062134] mode: 3 Oct 7 22:17:03 denkblock kernel: [ 240.062137] next_event: 240070000000 nsecs Oct 7 22:17:03 denkblock kernel: [ 240.062139] set_next_event: lapic_next_event Oct 7 22:17:03 denkblock kernel: [ 240.062145] set_mode: lapic_timer_setup Oct 7 22:17:03 denkblock kernel: [ 240.062150] event_handler: tick_nohz_handler Oct 7 22:17:03 denkblock kernel: [ 240.062155] --8<---------------dmesg---------------end--------------->8--- Please recall that ten seconds is the interval at which ath5k_calbrate() is executed. It is not always that the problem is triggered so regularly, but the elapsed time is always a multiple of ten seconds. Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-07 21:23 ` Elias Oltmanns @ 2008-10-08 11:39 ` Elias Oltmanns 2008-10-08 21:14 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-08 11:39 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Elias Oltmanns <eo@nebensachen.de> wrote: > Thomas Gleixner <tglx@linutronix.de> wrote: [...] >> Some more questions: >> >> Does this happen with any on the combinations of highres/nohz >> enabled/disabled ? > > From my tests in the past it would appear that NO_HZ enabled is the most > important option to trigger the problem speedily. HIGHRES_TIMERS didn't > seem to make much difference and I am quite sure that I observed this > issue with NO_HZ disabled too, but very rarely. I'll keep testing and > reporting. Meanwhile, ... As it turns out, it is all a bit different: Yesterday, I tried for quite some time to reproduce the problem on a system with both, NO_HZ and HIGH_RES_TIMERS disabled, but in vain. All other combinations trigger the described problem, so I have appended the requested data. There is one more odd thing: with NO_HZ disabled and HIGH_RES_TIMERS enabled, I cannot reliably associate with the AP (WPA encrypted). Still, the timer issue remains as you can see below and I rather suspect that this is a separate issue. Regards, Elias -------- # CONFIG_NO_HZ is not set CONFIG_HIGH_RES_TIMERS=y --8<---------------/proc/timer_list---------------start------------->8--- Timer List Version: v0.3 HRTIMER_MAX_CLOCK_BASES: 2 now at 67046247583 nsecs cpu: 0 clock 0: .index: 0 .resolution: 1 nsecs .get_time: ktime_get_real .offset: 1223456139058701991 nsecs active timers: clock 1: .index: 1 .resolution: 1 nsecs .get_time: ktime_get .offset: 0 nsecs active timers: #0: <df07aec0>, tick_sched_timer, S:01, tick_setup_sched_timer, modprobe/393 # expires at 67050000000 nsecs [in 3752417 nsecs] #1: <df07aec0>, it_real_fn, S:01, do_setitimer, syslogd/2441 # expires at 77308219646 nsecs [in 10261972063 nsecs] .expires_next : 67050000000 nsecs .hres_active : 1 .nr_events : 7039 .nohz_mode : 0 .idle_tick : 0 nsecs .tick_stopped : 0 .idle_jiffies : 0 .idle_calls : 0 .idle_sleeps : 0 .idle_entrytime : 0 nsecs .idle_waketime : 0 nsecs .idle_exittime : 0 nsecs .idle_sleeptime : 0 nsecs .last_jiffies : 0 .next_jiffies : 0 .idle_expires : 0 nsecs jiffies: 4294944000 Tick Device: mode: 1 Clock Event Device: pit max_delta_ns: 27461866 min_delta_ns: 12571 mult: 5124677 shift: 32 mode: 3 next_event: 67050000000 nsecs set_next_event: pit_next_event set_mode: init_pit_timer event_handler: tick_handle_oneshot_broadcast tick_broadcast_mask: 00000001 tick_broadcast_oneshot_mask: 00000000 Tick Device: mode: 1 Clock Event Device: lapic max_delta_ns: 1346509690 min_delta_ns: 2407 mult: 26757173 shift: 32 mode: 3 next_event: 67050000000 nsecs set_next_event: lapic_next_event set_mode: lapic_timer_setup event_handler: hrtimer_interrupt --8<---------------/proc/timer_list---------------end--------------->8--- --8<---------------dmesg---------------start------------->8--- Oct 8 10:56:52 denkblock kernel: [ 73.677706] timer-test: module successfully loaded. Oct 8 10:56:57 denkblock kernel: [ 78.625713] NET: Registered protocol family 17 Oct 8 10:57:17 denkblock kernel: [ 98.062731] b: 98.062701278 n: 98.062725024 e: 4294947102 j: 4294947102 Oct 8 10:57:17 denkblock kernel: [ 98.062740] Timer List Version: v0.3 Oct 8 10:57:17 denkblock kernel: [ 98.062743] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 10:57:17 denkblock kernel: [ 98.062746] now at 98062739551 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062748] Oct 8 10:57:17 denkblock kernel: [ 98.062751] cpu: 0 Oct 8 10:57:17 denkblock kernel: [ 98.062753] clock 0: Oct 8 10:57:17 denkblock kernel: [ 98.062755] .index: 0 Oct 8 10:57:17 denkblock kernel: [ 98.062757] .resolution: 1 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062760] .get_time: ktime_get_real Oct 8 10:57:17 denkblock kernel: [ 98.062771] .offset: 1223456139058701991 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062774] active timers: Oct 8 10:57:17 denkblock kernel: [ 98.062777] clock 1: Oct 8 10:57:17 denkblock kernel: [ 98.062780] .index: 1 Oct 8 10:57:17 denkblock kernel: [ 98.062782] .resolution: 1 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062784] .get_time: ktime_get Oct 8 10:57:17 denkblock kernel: [ 98.062790] .offset: 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062792] active timers: Oct 8 10:57:17 denkblock kernel: [ 98.062795] #0: softirq_stack, hrtick, S:01, hrtick_start_fair, swapper/0 Oct 8 10:57:17 denkblock kernel: [ 98.062813] # expires at 98066760424 nsecs [in 4020873 nsecs] Oct 8 10:57:17 denkblock kernel: [ 98.062817] #1: softirq_stack, tick_sched_timer, S:01, tick_setup_sched_timer, modprobe/393 Oct 8 10:57:17 denkblock kernel: [ 98.062833] # expires at 98070000000 nsecs [in 7260449 nsecs] Oct 8 10:57:17 denkblock kernel: [ 98.062836] #2: softirq_stack, hrtimer_wakeup, S:01, do_nanosleep, tail/2542 Oct 8 10:57:17 denkblock kernel: [ 98.062852] # expires at 98998620540 nsecs [in 935880989 nsecs] Oct 8 10:57:17 denkblock kernel: [ 98.062856] #3: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2441 Oct 8 10:57:17 denkblock kernel: [ 98.062870] # expires at 107308289209 nsecs [in 9245549658 nsecs] Oct 8 10:57:17 denkblock kernel: [ 98.062874] .expires_next : 98066760424 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062877] .hres_active : 1 Oct 8 10:57:17 denkblock kernel: [ 98.062880] .nr_events : 10206 Oct 8 10:57:17 denkblock kernel: [ 98.062883] .nohz_mode : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062886] .idle_tick : 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062888] .tick_stopped : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062891] .idle_jiffies : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062893] .idle_calls : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062896] .idle_sleeps : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062898] .idle_entrytime : 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062901] .idle_waketime : 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062904] .idle_exittime : 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062907] .idle_sleeptime : 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062910] .last_jiffies : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062912] .next_jiffies : 0 Oct 8 10:57:17 denkblock kernel: [ 98.062915] .idle_expires : 0 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062917] jiffies: 4294947102 Oct 8 10:57:17 denkblock kernel: [ 98.062920] Oct 8 10:57:17 denkblock kernel: [ 98.062921] Oct 8 10:57:17 denkblock kernel: [ 98.062924] Tick Device: mode: 1 Oct 8 10:57:17 denkblock kernel: [ 98.062926] Clock Event Device: pit Oct 8 10:57:17 denkblock kernel: [ 98.062930] max_delta_ns: 27461866 Oct 8 10:57:17 denkblock kernel: [ 98.062933] min_delta_ns: 12571 Oct 8 10:57:17 denkblock kernel: [ 98.062936] mult: 5124677 Oct 8 10:57:17 denkblock kernel: [ 98.062938] shift: 32 Oct 8 10:57:17 denkblock kernel: [ 98.062941] mode: 3 Oct 8 10:57:17 denkblock kernel: [ 98.062944] next_event: 9223372036854775807 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062947] set_next_event: pit_next_event Oct 8 10:57:17 denkblock kernel: [ 98.062954] set_mode: init_pit_timer Oct 8 10:57:17 denkblock kernel: [ 98.062960] event_handler: tick_handle_oneshot_broadcast Oct 8 10:57:17 denkblock kernel: [ 98.062966] tick_broadcast_mask: 00000001 Oct 8 10:57:17 denkblock kernel: [ 98.062969] tick_broadcast_oneshot_mask: 00000000 Oct 8 10:57:17 denkblock kernel: [ 98.062971] Oct 8 10:57:17 denkblock kernel: [ 98.062973] Oct 8 10:57:17 denkblock kernel: [ 98.062975] Tick Device: mode: 1 Oct 8 10:57:17 denkblock kernel: [ 98.062978] Clock Event Device: lapic Oct 8 10:57:17 denkblock kernel: [ 98.062981] max_delta_ns: 1346509690 Oct 8 10:57:17 denkblock kernel: [ 98.062984] min_delta_ns: 2407 Oct 8 10:57:17 denkblock kernel: [ 98.062987] mult: 26757173 Oct 8 10:57:17 denkblock kernel: [ 98.062990] shift: 32 Oct 8 10:57:17 denkblock kernel: [ 98.062992] mode: 3 Oct 8 10:57:17 denkblock kernel: [ 98.062995] next_event: 98066760424 nsecs Oct 8 10:57:17 denkblock kernel: [ 98.062998] set_next_event: lapic_next_event Oct 8 10:57:17 denkblock kernel: [ 98.063003] set_mode: lapic_timer_setup Oct 8 10:57:17 denkblock kernel: [ 98.063008] event_handler: hrtimer_interrupt Oct 8 10:57:17 denkblock kernel: [ 98.063013] Oct 8 10:57:37 denkblock kernel: [ 118.064044] b: 118.064013752 n: 118.064037777 e: 4294949102 j: 4294949102 Oct 8 10:57:37 denkblock kernel: [ 118.064053] Timer List Version: v0.3 Oct 8 10:57:37 denkblock kernel: [ 118.064056] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 10:57:37 denkblock kernel: [ 118.064059] now at 118064052584 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064062] Oct 8 10:57:37 denkblock kernel: [ 118.064064] cpu: 0 Oct 8 10:57:37 denkblock kernel: [ 118.064066] clock 0: Oct 8 10:57:37 denkblock kernel: [ 118.064068] .index: 0 Oct 8 10:57:37 denkblock kernel: [ 118.064071] .resolution: 1 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064073] .get_time: ktime_get_real Oct 8 10:57:37 denkblock kernel: [ 118.064085] .offset: 1223456139058701991 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064088] active timers: Oct 8 10:57:37 denkblock kernel: [ 118.064091] clock 1: Oct 8 10:57:37 denkblock kernel: [ 118.064093] .index: 1 Oct 8 10:57:37 denkblock kernel: [ 118.064096] .resolution: 1 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064098] .get_time: ktime_get Oct 8 10:57:37 denkblock kernel: [ 118.064103] .offset: 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064106] active timers: Oct 8 10:57:37 denkblock kernel: [ 118.064109] #0: softirq_stack, tick_sched_timer, S:01, tick_setup_sched_timer, modprobe/393 Oct 8 10:57:37 denkblock kernel: [ 118.064128] # expires at 118070000000 nsecs [in 5947416 nsecs] Oct 8 10:57:37 denkblock kernel: [ 118.064132] #1: softirq_stack, hrtick, S:01, hrtick_start_fair, swapper/0 Oct 8 10:57:37 denkblock kernel: [ 118.064147] # expires at 118077280701 nsecs [in 13228117 nsecs] Oct 8 10:57:37 denkblock kernel: [ 118.064150] #2: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2441 Oct 8 10:57:37 denkblock kernel: [ 118.064164] # expires at 137327440208 nsecs [in 19263387624 nsecs] Oct 8 10:57:37 denkblock kernel: [ 118.064169] .expires_next : 118070000000 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064172] .hres_active : 1 Oct 8 10:57:37 denkblock kernel: [ 118.064174] .nr_events : 12269 Oct 8 10:57:37 denkblock kernel: [ 118.064177] .nohz_mode : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064180] .idle_tick : 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064183] .tick_stopped : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064185] .idle_jiffies : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064188] .idle_calls : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064190] .idle_sleeps : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064193] .idle_entrytime : 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064196] .idle_waketime : 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064199] .idle_exittime : 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064201] .idle_sleeptime : 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064204] .last_jiffies : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064207] .next_jiffies : 0 Oct 8 10:57:37 denkblock kernel: [ 118.064209] .idle_expires : 0 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064212] jiffies: 4294949102 Oct 8 10:57:37 denkblock kernel: [ 118.064214] Oct 8 10:57:37 denkblock kernel: [ 118.064216] Oct 8 10:57:37 denkblock kernel: [ 118.064218] Tick Device: mode: 1 Oct 8 10:57:37 denkblock kernel: [ 118.064221] Clock Event Device: pit Oct 8 10:57:37 denkblock kernel: [ 118.064225] max_delta_ns: 27461866 Oct 8 10:57:37 denkblock kernel: [ 118.064228] min_delta_ns: 12571 Oct 8 10:57:37 denkblock kernel: [ 118.064230] mult: 5124677 Oct 8 10:57:37 denkblock kernel: [ 118.064233] shift: 32 Oct 8 10:57:37 denkblock kernel: [ 118.064235] mode: 3 Oct 8 10:57:37 denkblock kernel: [ 118.064239] next_event: 9223372036854775807 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064241] set_next_event: pit_next_event Oct 8 10:57:37 denkblock kernel: [ 118.064249] set_mode: init_pit_timer Oct 8 10:57:37 denkblock kernel: [ 118.064254] event_handler: tick_handle_oneshot_broadcast Oct 8 10:57:37 denkblock kernel: [ 118.064260] tick_broadcast_mask: 00000001 Oct 8 10:57:37 denkblock kernel: [ 118.064263] tick_broadcast_oneshot_mask: 00000000 Oct 8 10:57:37 denkblock kernel: [ 118.064266] Oct 8 10:57:37 denkblock kernel: [ 118.064268] Oct 8 10:57:37 denkblock kernel: [ 118.064270] Tick Device: mode: 1 Oct 8 10:57:37 denkblock kernel: [ 118.064272] Clock Event Device: lapic Oct 8 10:57:37 denkblock kernel: [ 118.064276] max_delta_ns: 1346509690 Oct 8 10:57:37 denkblock kernel: [ 118.064279] min_delta_ns: 2407 Oct 8 10:57:37 denkblock kernel: [ 118.064281] mult: 26757173 Oct 8 10:57:37 denkblock kernel: [ 118.064284] shift: 32 Oct 8 10:57:37 denkblock kernel: [ 118.064287] mode: 3 Oct 8 10:57:37 denkblock kernel: [ 118.064289] next_event: 118070000000 nsecs Oct 8 10:57:37 denkblock kernel: [ 118.064292] set_next_event: lapic_next_event Oct 8 10:57:37 denkblock kernel: [ 118.064298] set_mode: lapic_timer_setup Oct 8 10:57:37 denkblock kernel: [ 118.064303] event_handler: hrtimer_interrupt Oct 8 10:57:37 denkblock kernel: [ 118.064308] Oct 8 10:57:57 denkblock kernel: [ 138.064041] b: 138.064013472 n: 138.064034984 e: 4294951102 j: 4294951102 Oct 8 10:57:57 denkblock kernel: [ 138.064049] Timer List Version: v0.3 Oct 8 10:57:57 denkblock kernel: [ 138.064052] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 10:57:57 denkblock kernel: [ 138.064055] now at 138064048673 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064058] Oct 8 10:57:57 denkblock kernel: [ 138.064060] cpu: 0 Oct 8 10:57:57 denkblock kernel: [ 138.064062] clock 0: Oct 8 10:57:57 denkblock kernel: [ 138.064064] .index: 0 Oct 8 10:57:57 denkblock kernel: [ 138.064067] .resolution: 1 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064070] .get_time: ktime_get_real Oct 8 10:57:57 denkblock kernel: [ 138.064081] .offset: 1223456139058701991 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064084] active timers: Oct 8 10:57:57 denkblock kernel: [ 138.064087] clock 1: Oct 8 10:57:57 denkblock kernel: [ 138.064090] .index: 1 Oct 8 10:57:57 denkblock kernel: [ 138.064092] .resolution: 1 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064094] .get_time: ktime_get Oct 8 10:57:57 denkblock kernel: [ 138.064100] .offset: 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064102] active timers: Oct 8 10:57:57 denkblock kernel: [ 138.064105] #0: softirq_stack, hrtick, S:01, hrtick_start_fair, swapper/0 Oct 8 10:57:57 denkblock kernel: [ 138.064123] # expires at 138068961552 nsecs [in 4912879 nsecs] Oct 8 10:57:57 denkblock kernel: [ 138.064127] #1: softirq_stack, tick_sched_timer, S:01, tick_setup_sched_timer, modprobe/393 Oct 8 10:57:57 denkblock kernel: [ 138.064143] # expires at 138070000000 nsecs [in 5951327 nsecs] Oct 8 10:57:57 denkblock kernel: [ 138.064147] #2: softirq_stack, hrtimer_wakeup, S:01, do_nanosleep, tail/2542 Oct 8 10:57:57 denkblock kernel: [ 138.064163] # expires at 138157525136 nsecs [in 93476463 nsecs] Oct 8 10:57:57 denkblock kernel: [ 138.064166] #3: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2441 Oct 8 10:57:57 denkblock kernel: [ 138.064180] # expires at 167327501110 nsecs [in 29263452437 nsecs] Oct 8 10:57:57 denkblock kernel: [ 138.064185] .expires_next : 138068961552 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064188] .hres_active : 1 Oct 8 10:57:57 denkblock kernel: [ 138.064190] .nr_events : 14329 Oct 8 10:57:57 denkblock kernel: [ 138.064193] .nohz_mode : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064196] .idle_tick : 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064199] .tick_stopped : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064201] .idle_jiffies : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064204] .idle_calls : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064206] .idle_sleeps : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064209] .idle_entrytime : 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064212] .idle_waketime : 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064215] .idle_exittime : 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064218] .idle_sleeptime : 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064220] .last_jiffies : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064223] .next_jiffies : 0 Oct 8 10:57:57 denkblock kernel: [ 138.064225] .idle_expires : 0 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064228] jiffies: 4294951102 Oct 8 10:57:57 denkblock kernel: [ 138.064230] Oct 8 10:57:57 denkblock kernel: [ 138.064232] Oct 8 10:57:57 denkblock kernel: [ 138.064234] Tick Device: mode: 1 Oct 8 10:57:57 denkblock kernel: [ 138.064237] Clock Event Device: pit Oct 8 10:57:57 denkblock kernel: [ 138.064241] max_delta_ns: 27461866 Oct 8 10:57:57 denkblock kernel: [ 138.064244] min_delta_ns: 12571 Oct 8 10:57:57 denkblock kernel: [ 138.064247] mult: 5124677 Oct 8 10:57:57 denkblock kernel: [ 138.064249] shift: 32 Oct 8 10:57:57 denkblock kernel: [ 138.064252] mode: 3 Oct 8 10:57:57 denkblock kernel: [ 138.064255] next_event: 9223372036854775807 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064258] set_next_event: pit_next_event Oct 8 10:57:57 denkblock kernel: [ 138.064265] set_mode: init_pit_timer Oct 8 10:57:57 denkblock kernel: [ 138.064271] event_handler: tick_handle_oneshot_broadcast Oct 8 10:57:57 denkblock kernel: [ 138.064277] tick_broadcast_mask: 00000001 Oct 8 10:57:57 denkblock kernel: [ 138.064280] tick_broadcast_oneshot_mask: 00000000 Oct 8 10:57:57 denkblock kernel: [ 138.064282] Oct 8 10:57:57 denkblock kernel: [ 138.064284] Oct 8 10:57:57 denkblock kernel: [ 138.064286] Tick Device: mode: 1 Oct 8 10:57:57 denkblock kernel: [ 138.064289] Clock Event Device: lapic Oct 8 10:57:57 denkblock kernel: [ 138.064292] max_delta_ns: 1346509690 Oct 8 10:57:57 denkblock kernel: [ 138.064295] min_delta_ns: 2407 Oct 8 10:57:57 denkblock kernel: [ 138.064298] mult: 26757173 Oct 8 10:57:57 denkblock kernel: [ 138.064301] shift: 32 Oct 8 10:57:57 denkblock kernel: [ 138.064303] mode: 3 Oct 8 10:57:57 denkblock kernel: [ 138.064306] next_event: 138068961552 nsecs Oct 8 10:57:57 denkblock kernel: [ 138.064309] set_next_event: lapic_next_event Oct 8 10:57:57 denkblock kernel: [ 138.064314] set_mode: lapic_timer_setup Oct 8 10:57:57 denkblock kernel: [ 138.064319] event_handler: hrtimer_interrupt Oct 8 10:57:57 denkblock kernel: [ 138.064324] Oct 8 10:58:07 denkblock kernel: [ 148.064037] b: 148.064007606 n: 148.064029676 e: 4294952102 j: 4294952102 Oct 8 10:58:07 denkblock kernel: [ 148.064045] Timer List Version: v0.3 Oct 8 10:58:07 denkblock kernel: [ 148.064048] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 10:58:07 denkblock kernel: [ 148.064051] now at 148064045041 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064054] Oct 8 10:58:07 denkblock kernel: [ 148.064057] cpu: 0 Oct 8 10:58:07 denkblock kernel: [ 148.064059] clock 0: Oct 8 10:58:07 denkblock kernel: [ 148.064061] .index: 0 Oct 8 10:58:07 denkblock kernel: [ 148.064064] .resolution: 1 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064066] .get_time: ktime_get_real Oct 8 10:58:07 denkblock kernel: [ 148.064078] .offset: 1223456139058701991 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064081] active timers: Oct 8 10:58:07 denkblock kernel: [ 148.064084] clock 1: Oct 8 10:58:07 denkblock kernel: [ 148.064086] .index: 1 Oct 8 10:58:07 denkblock kernel: [ 148.064089] .resolution: 1 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064091] .get_time: ktime_get Oct 8 10:58:07 denkblock kernel: [ 148.064097] .offset: 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064099] active timers: Oct 8 10:58:07 denkblock kernel: [ 148.064102] #0: softirq_stack, tick_sched_timer, S:01, tick_setup_sched_timer, modprobe/393 Oct 8 10:58:07 denkblock kernel: [ 148.064121] # expires at 148070000000 nsecs [in 5954959 nsecs] Oct 8 10:58:07 denkblock kernel: [ 148.064125] #1: softirq_stack, hrtick, S:01, hrtick_start_fair, swapper/0 Oct 8 10:58:07 denkblock kernel: [ 148.064141] # expires at 148074015223 nsecs [in 9970182 nsecs] Oct 8 10:58:07 denkblock kernel: [ 148.064145] #2: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2441 Oct 8 10:58:07 denkblock kernel: [ 148.064158] # expires at 167327501110 nsecs [in 19263456069 nsecs] Oct 8 10:58:07 denkblock kernel: [ 148.064163] .expires_next : 148070000000 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064166] .hres_active : 1 Oct 8 10:58:07 denkblock kernel: [ 148.064169] .nr_events : 15358 Oct 8 10:58:07 denkblock kernel: [ 148.064172] .nohz_mode : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064174] .idle_tick : 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064177] .tick_stopped : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064180] .idle_jiffies : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064182] .idle_calls : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064185] .idle_sleeps : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064187] .idle_entrytime : 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064190] .idle_waketime : 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064193] .idle_exittime : 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064196] .idle_sleeptime : 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064198] .last_jiffies : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064201] .next_jiffies : 0 Oct 8 10:58:07 denkblock kernel: [ 148.064204] .idle_expires : 0 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064206] jiffies: 4294952102 Oct 8 10:58:07 denkblock kernel: [ 148.064209] Oct 8 10:58:07 denkblock kernel: [ 148.064210] Oct 8 10:58:07 denkblock kernel: [ 148.064213] Tick Device: mode: 1 Oct 8 10:58:07 denkblock kernel: [ 148.064215] Clock Event Device: pit Oct 8 10:58:07 denkblock kernel: [ 148.064219] max_delta_ns: 27461866 Oct 8 10:58:07 denkblock kernel: [ 148.064222] min_delta_ns: 12571 Oct 8 10:58:07 denkblock kernel: [ 148.064224] mult: 5124677 Oct 8 10:58:07 denkblock kernel: [ 148.064227] shift: 32 Oct 8 10:58:07 denkblock kernel: [ 148.064230] mode: 3 Oct 8 10:58:07 denkblock kernel: [ 148.064233] next_event: 9223372036854775807 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064236] set_next_event: pit_next_event Oct 8 10:58:07 denkblock kernel: [ 148.064243] set_mode: init_pit_timer Oct 8 10:58:07 denkblock kernel: [ 148.064248] event_handler: tick_handle_oneshot_broadcast Oct 8 10:58:07 denkblock kernel: [ 148.064255] tick_broadcast_mask: 00000001 Oct 8 10:58:07 denkblock kernel: [ 148.064258] tick_broadcast_oneshot_mask: 00000000 Oct 8 10:58:07 denkblock kernel: [ 148.064261] Oct 8 10:58:07 denkblock kernel: [ 148.064262] Oct 8 10:58:07 denkblock kernel: [ 148.064265] Tick Device: mode: 1 Oct 8 10:58:07 denkblock kernel: [ 148.064267] Clock Event Device: lapic Oct 8 10:58:07 denkblock kernel: [ 148.064271] max_delta_ns: 1346509690 Oct 8 10:58:07 denkblock kernel: [ 148.064273] min_delta_ns: 2407 Oct 8 10:58:07 denkblock kernel: [ 148.064276] mult: 26757173 Oct 8 10:58:07 denkblock kernel: [ 148.064279] shift: 32 Oct 8 10:58:07 denkblock kernel: [ 148.064281] mode: 3 Oct 8 10:58:07 denkblock kernel: [ 148.064284] next_event: 148070000000 nsecs Oct 8 10:58:07 denkblock kernel: [ 148.064287] set_next_event: lapic_next_event Oct 8 10:58:07 denkblock kernel: [ 148.064293] set_mode: lapic_timer_setup Oct 8 10:58:07 denkblock kernel: [ 148.064298] event_handler: hrtimer_interrupt Oct 8 10:58:07 denkblock kernel: [ 148.064303] Oct 8 10:58:49 denkblock kernel: [ 190.237540] tstm: module unloaded. --8<---------------dmesg---------------end--------------->8--- CONFIG_NO_HZ=y CONFIG_HIGH_RES_TIMERS=y --8<---------------/proc/timer_list---------------start------------->8--- Timer List Version: v0.3 HRTIMER_MAX_CLOCK_BASES: 2 now at 92466531281 nsecs cpu: 0 clock 0: .index: 0 .resolution: 1 nsecs .get_time: ktime_get_real .offset: 1223464145158820160 nsecs active timers: clock 1: .index: 1 .resolution: 1 nsecs .get_time: ktime_get .offset: 0 nsecs active timers: #0: <df19bec0>, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0 # expires at 92470000000 nsecs [in 3468719 nsecs] #1: <df19bec0>, it_real_fn, S:01, do_setitimer, syslogd/2439 # expires at 120911077291 nsecs [in 28444546010 nsecs] .expires_next : 92470000000 nsecs .hres_active : 1 .nr_events : 3400 .nohz_mode : 2 .idle_tick : 92440000000 nsecs .tick_stopped : 0 .idle_jiffies : 4294946539 .idle_calls : 14205 .idle_sleeps : 10925 .idle_entrytime : 92457842744 nsecs .idle_waketime : 92464993097 nsecs .idle_exittime : 92465047014 nsecs .idle_sleeptime : 81875451152 nsecs .last_jiffies : 4294946541 .next_jiffies : 4294946543 .idle_expires : 92470000000 nsecs jiffies: 4294946542 Tick Device: mode: 1 Clock Event Device: pit max_delta_ns: 27461866 min_delta_ns: 12571 mult: 5124677 shift: 32 mode: 3 next_event: 92470000000 nsecs set_next_event: pit_next_event set_mode: init_pit_timer event_handler: tick_handle_oneshot_broadcast tick_broadcast_mask: 00000001 tick_broadcast_oneshot_mask: 00000000 Tick Device: mode: 1 Clock Event Device: lapic max_delta_ns: 1346509690 min_delta_ns: 2407 mult: 26757173 shift: 32 mode: 3 next_event: 92470000000 nsecs set_next_event: lapic_next_event set_mode: lapic_timer_setup event_handler: hrtimer_interrupt --8<---------------/proc/timer_list---------------end--------------->8--- --8<---------------dmesg---------------start------------->8--- Oct 8 13:10:48 denkblock kernel: [ 103.490553] timer-test: module successfully loaded. Oct 8 13:10:55 denkblock kernel: [ 110.084616] NET: Registered protocol family 17 [Associate with AP] Oct 8 13:12:35 denkblock kernel: [ 210.062290] b: 210.062258000 n: 210.062284260 e: 4294958302 j: 4294958302 Oct 8 13:12:35 denkblock kernel: [ 210.062297] Timer List Version: v0.3 Oct 8 13:12:35 denkblock kernel: [ 210.062300] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 13:12:35 denkblock kernel: [ 210.062303] now at 210062297111 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062306] Oct 8 13:12:35 denkblock kernel: [ 210.062308] cpu: 0 Oct 8 13:12:35 denkblock kernel: [ 210.062310] clock 0: Oct 8 13:12:35 denkblock kernel: [ 210.062312] .index: 0 Oct 8 13:12:35 denkblock kernel: [ 210.062315] .resolution: 1 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062317] .get_time: ktime_get_real Oct 8 13:12:35 denkblock kernel: [ 210.062330] .offset: 1223464145147675602 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062332] active timers: Oct 8 13:12:35 denkblock kernel: [ 210.062335] clock 1: Oct 8 13:12:35 denkblock kernel: [ 210.062338] .index: 1 Oct 8 13:12:35 denkblock kernel: [ 210.062340] .resolution: 1 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062342] .get_time: ktime_get Oct 8 13:12:35 denkblock kernel: [ 210.062348] .offset: 0 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062350] active timers: Oct 8 13:12:35 denkblock kernel: [ 210.062353] #0: softirq_stack, hrtick, S:01, hrtick_start_fair, events/0/4 Oct 8 13:12:35 denkblock kernel: [ 210.062371] # expires at 210064209333 nsecs [in 1912222 nsecs] Oct 8 13:12:35 denkblock kernel: [ 210.062375] #1: softirq_stack, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0 Oct 8 13:12:35 denkblock kernel: [ 210.062391] # expires at 210070000000 nsecs [in 7702889 nsecs] Oct 8 13:12:35 denkblock kernel: [ 210.062394] #2: softirq_stack, hrtimer_wakeup, S:01, do_nanosleep, tail/2537 Oct 8 13:12:35 denkblock kernel: [ 210.062410] # expires at 210767716572 nsecs [in 705419461 nsecs] Oct 8 13:12:35 denkblock kernel: [ 210.062414] #3: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2439 Oct 8 13:12:35 denkblock kernel: [ 210.062427] # expires at 210911270052 nsecs [in 848972941 nsecs] Oct 8 13:12:35 denkblock kernel: [ 210.062432] .expires_next : 210064209333 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062435] .hres_active : 1 Oct 8 13:12:35 denkblock kernel: [ 210.062438] .nr_events : 10923 Oct 8 13:12:35 denkblock kernel: [ 210.062440] .nohz_mode : 2 Oct 8 13:12:35 denkblock kernel: [ 210.062443] .idle_tick : 210030000000 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062446] .tick_stopped : 0 Oct 8 13:12:35 denkblock kernel: [ 210.062449] .idle_jiffies : 4294958298 Oct 8 13:12:35 denkblock kernel: [ 210.062452] .idle_calls : 32020 Oct 8 13:12:35 denkblock kernel: [ 210.062454] .idle_sleeps : 23265 Oct 8 13:12:35 denkblock kernel: [ 210.062457] .idle_entrytime : 210032869899 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062461] .idle_waketime : 210032831905 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062464] .idle_exittime : 210032853416 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062467] .idle_sleeptime : 195265042635 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062470] .last_jiffies : 4294958299 Oct 8 13:12:35 denkblock kernel: [ 210.062473] .next_jiffies : 4294958300 Oct 8 13:12:35 denkblock kernel: [ 210.062476] .idle_expires : 210040000000 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062479] jiffies: 4294958302 Oct 8 13:12:35 denkblock kernel: [ 210.062481] Oct 8 13:12:35 denkblock kernel: [ 210.062483] Oct 8 13:12:35 denkblock kernel: [ 210.062485] Tick Device: mode: 1 Oct 8 13:12:35 denkblock kernel: [ 210.062487] Clock Event Device: pit Oct 8 13:12:35 denkblock kernel: [ 210.062491] max_delta_ns: 27461866 Oct 8 13:12:35 denkblock kernel: [ 210.062494] min_delta_ns: 12571 Oct 8 13:12:35 denkblock kernel: [ 210.062497] mult: 5124677 Oct 8 13:12:35 denkblock kernel: [ 210.062499] shift: 32 Oct 8 13:12:35 denkblock kernel: [ 210.062502] mode: 3 Oct 8 13:12:35 denkblock kernel: [ 210.062505] next_event: 9223372036854775807 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062507] set_next_event: pit_next_event Oct 8 13:12:35 denkblock kernel: [ 210.062515] set_mode: init_pit_timer Oct 8 13:12:35 denkblock kernel: [ 210.062520] event_handler: tick_handle_oneshot_broadcast Oct 8 13:12:35 denkblock kernel: [ 210.062526] tick_broadcast_mask: 00000001 Oct 8 13:12:35 denkblock kernel: [ 210.062529] tick_broadcast_oneshot_mask: 00000000 Oct 8 13:12:35 denkblock kernel: [ 210.062531] Oct 8 13:12:35 denkblock kernel: [ 210.062533] Oct 8 13:12:35 denkblock kernel: [ 210.062535] Tick Device: mode: 1 Oct 8 13:12:35 denkblock kernel: [ 210.062537] Clock Event Device: lapic Oct 8 13:12:35 denkblock kernel: [ 210.062541] max_delta_ns: 1346509690 Oct 8 13:12:35 denkblock kernel: [ 210.062544] min_delta_ns: 2407 Oct 8 13:12:35 denkblock kernel: [ 210.062546] mult: 26757173 Oct 8 13:12:35 denkblock kernel: [ 210.062549] shift: 32 Oct 8 13:12:35 denkblock kernel: [ 210.062551] mode: 3 Oct 8 13:12:35 denkblock kernel: [ 210.062554] next_event: 210064209333 nsecs Oct 8 13:12:35 denkblock kernel: [ 210.062557] set_next_event: lapic_next_event Oct 8 13:12:35 denkblock kernel: [ 210.062562] set_mode: lapic_timer_setup Oct 8 13:12:35 denkblock kernel: [ 210.062567] event_handler: hrtimer_interrupt Oct 8 13:12:35 denkblock kernel: [ 210.062572] Oct 8 13:13:05 denkblock kernel: [ 240.062779] b: 240.062741022 n: 240.062773428 e: 4294961302 j: 4294961302 Oct 8 13:13:05 denkblock kernel: [ 240.062786] Timer List Version: v0.3 Oct 8 13:13:05 denkblock kernel: [ 240.062789] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 13:13:05 denkblock kernel: [ 240.062792] now at 240062786000 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062795] Oct 8 13:13:05 denkblock kernel: [ 240.062797] cpu: 0 Oct 8 13:13:05 denkblock kernel: [ 240.062799] clock 0: Oct 8 13:13:05 denkblock kernel: [ 240.062801] .index: 0 Oct 8 13:13:05 denkblock kernel: [ 240.062804] .resolution: 1 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062806] .get_time: ktime_get_real Oct 8 13:13:05 denkblock kernel: [ 240.062818] .offset: 1223464145147675602 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062820] active timers: Oct 8 13:13:05 denkblock kernel: [ 240.062823] clock 1: Oct 8 13:13:05 denkblock kernel: [ 240.062826] .index: 1 Oct 8 13:13:05 denkblock kernel: [ 240.062828] .resolution: 1 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062830] .get_time: ktime_get Oct 8 13:13:05 denkblock kernel: [ 240.062836] .offset: 0 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062838] active timers: Oct 8 13:13:05 denkblock kernel: [ 240.062841] #0: softirq_stack, hrtick, S:01, hrtick_start_fair, events/0/4 Oct 8 13:13:05 denkblock kernel: [ 240.062859] # expires at 240064208834 nsecs [in 1422834 nsecs] Oct 8 13:13:05 denkblock kernel: [ 240.062863] #1: softirq_stack, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0 Oct 8 13:13:05 denkblock kernel: [ 240.062879] # expires at 240070000000 nsecs [in 7214000 nsecs] Oct 8 13:13:05 denkblock kernel: [ 240.062882] #2: softirq_stack, hrtimer_wakeup, S:01, do_nanosleep, tail/2537 Oct 8 13:13:05 denkblock kernel: [ 240.062898] # expires at 240779253796 nsecs [in 716467796 nsecs] Oct 8 13:13:05 denkblock kernel: [ 240.062902] #3: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2439 Oct 8 13:13:05 denkblock kernel: [ 240.062915] # expires at 240911335424 nsecs [in 848549424 nsecs] Oct 8 13:13:05 denkblock kernel: [ 240.062919] .expires_next : 240064208834 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062922] .hres_active : 1 Oct 8 13:13:05 denkblock kernel: [ 240.062925] .nr_events : 12900 Oct 8 13:13:05 denkblock kernel: [ 240.062928] .nohz_mode : 2 Oct 8 13:13:05 denkblock kernel: [ 240.062931] .idle_tick : 240030000000 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062934] .tick_stopped : 0 Oct 8 13:13:05 denkblock kernel: [ 240.062937] .idle_jiffies : 4294961298 Oct 8 13:13:05 denkblock kernel: [ 240.062939] .idle_calls : 36766 Oct 8 13:13:05 denkblock kernel: [ 240.062942] .idle_sleeps : 26548 Oct 8 13:13:05 denkblock kernel: [ 240.062945] .idle_entrytime : 240036511983 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062948] .idle_waketime : 240036475107 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062951] .idle_exittime : 240036495500 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062955] .idle_sleeptime : 224964920586 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062958] .last_jiffies : 4294961299 Oct 8 13:13:05 denkblock kernel: [ 240.062960] .next_jiffies : 4294961300 Oct 8 13:13:05 denkblock kernel: [ 240.062963] .idle_expires : 240040000000 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062967] jiffies: 4294961302 Oct 8 13:13:05 denkblock kernel: [ 240.062969] Oct 8 13:13:05 denkblock kernel: [ 240.062970] Oct 8 13:13:05 denkblock kernel: [ 240.062973] Tick Device: mode: 1 Oct 8 13:13:05 denkblock kernel: [ 240.062975] Clock Event Device: pit Oct 8 13:13:05 denkblock kernel: [ 240.062979] max_delta_ns: 27461866 Oct 8 13:13:05 denkblock kernel: [ 240.062982] min_delta_ns: 12571 Oct 8 13:13:05 denkblock kernel: [ 240.062984] mult: 5124677 Oct 8 13:13:05 denkblock kernel: [ 240.062987] shift: 32 Oct 8 13:13:05 denkblock kernel: [ 240.062989] mode: 3 Oct 8 13:13:05 denkblock kernel: [ 240.062992] next_event: 9223372036854775807 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.062995] set_next_event: pit_next_event Oct 8 13:13:05 denkblock kernel: [ 240.063002] set_mode: init_pit_timer Oct 8 13:13:05 denkblock kernel: [ 240.063008] event_handler: tick_handle_oneshot_broadcast Oct 8 13:13:05 denkblock kernel: [ 240.063014] tick_broadcast_mask: 00000001 Oct 8 13:13:05 denkblock kernel: [ 240.063016] tick_broadcast_oneshot_mask: 00000000 Oct 8 13:13:05 denkblock kernel: [ 240.063019] Oct 8 13:13:05 denkblock kernel: [ 240.063021] Oct 8 13:13:05 denkblock kernel: [ 240.063023] Tick Device: mode: 1 Oct 8 13:13:05 denkblock kernel: [ 240.063025] Clock Event Device: lapic Oct 8 13:13:05 denkblock kernel: [ 240.063029] max_delta_ns: 1346509690 Oct 8 13:13:05 denkblock kernel: [ 240.063031] min_delta_ns: 2407 Oct 8 13:13:05 denkblock kernel: [ 240.063034] mult: 26757173 Oct 8 13:13:05 denkblock kernel: [ 240.063037] shift: 32 Oct 8 13:13:05 denkblock kernel: [ 240.063039] mode: 3 Oct 8 13:13:05 denkblock kernel: [ 240.063042] next_event: 240064208834 nsecs Oct 8 13:13:05 denkblock kernel: [ 240.063044] set_next_event: lapic_next_event Oct 8 13:13:05 denkblock kernel: [ 240.063050] set_mode: lapic_timer_setup Oct 8 13:13:05 denkblock kernel: [ 240.063055] event_handler: hrtimer_interrupt Oct 8 13:13:05 denkblock kernel: [ 240.063060] Oct 8 13:13:15 denkblock kernel: [ 250.062990] b: 250.062950825 n: 250.062983790 e: 4294962302 j: 4294962302 Oct 8 13:13:15 denkblock kernel: [ 250.062997] Timer List Version: v0.3 Oct 8 13:13:15 denkblock kernel: [ 250.063000] HRTIMER_MAX_CLOCK_BASES: 2 Oct 8 13:13:15 denkblock kernel: [ 250.063003] now at 250062996641 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063005] Oct 8 13:13:15 denkblock kernel: [ 250.063008] cpu: 0 Oct 8 13:13:15 denkblock kernel: [ 250.063010] clock 0: Oct 8 13:13:15 denkblock kernel: [ 250.063012] .index: 0 Oct 8 13:13:15 denkblock kernel: [ 250.063014] .resolution: 1 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063017] .get_time: ktime_get_real Oct 8 13:13:15 denkblock kernel: [ 250.063028] .offset: 1223464145147675602 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063031] active timers: Oct 8 13:13:15 denkblock kernel: [ 250.063034] clock 1: Oct 8 13:13:15 denkblock kernel: [ 250.063036] .index: 1 Oct 8 13:13:15 denkblock kernel: [ 250.063038] .resolution: 1 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063041] .get_time: ktime_get Oct 8 13:13:15 denkblock kernel: [ 250.063046] .offset: 0 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063048] active timers: Oct 8 13:13:15 denkblock kernel: [ 250.063051] #0: softirq_stack, hrtick, S:01, hrtick_start_fair, events/0/4 Oct 8 13:13:15 denkblock kernel: [ 250.063069] # expires at 250064208152 nsecs [in 1211511 nsecs] Oct 8 13:13:15 denkblock kernel: [ 250.063073] #1: softirq_stack, tick_sched_timer, S:01, tick_nohz_restart_sched_tick, swapper/0 Oct 8 13:13:15 denkblock kernel: [ 250.063089] # expires at 250070000000 nsecs [in 7003359 nsecs] Oct 8 13:13:15 denkblock kernel: [ 250.063093] #2: softirq_stack, it_real_fn, S:01, do_setitimer, syslogd/2439 Oct 8 13:13:15 denkblock kernel: [ 250.063106] # expires at 270911403868 nsecs [in 20848407227 nsecs] Oct 8 13:13:15 denkblock kernel: [ 250.063111] .expires_next : 250064208152 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063114] .hres_active : 1 Oct 8 13:13:15 denkblock kernel: [ 250.063117] .nr_events : 13549 Oct 8 13:13:15 denkblock kernel: [ 250.063119] .nohz_mode : 2 Oct 8 13:13:15 denkblock kernel: [ 250.063122] .idle_tick : 250030000000 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063125] .tick_stopped : 0 Oct 8 13:13:15 denkblock kernel: [ 250.063128] .idle_jiffies : 4294962298 Oct 8 13:13:15 denkblock kernel: [ 250.063131] .idle_calls : 38321 Oct 8 13:13:15 denkblock kernel: [ 250.063133] .idle_sleeps : 27609 Oct 8 13:13:15 denkblock kernel: [ 250.063136] .idle_entrytime : 250031169962 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063139] .idle_waketime : 250030532730 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063143] .idle_exittime : 250030556196 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063146] .idle_sleeptime : 234773018770 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063149] .last_jiffies : 4294962299 Oct 8 13:13:15 denkblock kernel: [ 250.063156] .next_jiffies : 4294962300 Oct 8 13:13:15 denkblock kernel: [ 250.063159] .idle_expires : 250040000000 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063162] jiffies: 4294962302 Oct 8 13:13:15 denkblock kernel: [ 250.063164] Oct 8 13:13:15 denkblock kernel: [ 250.063166] Oct 8 13:13:15 denkblock kernel: [ 250.063168] Tick Device: mode: 1 Oct 8 13:13:15 denkblock kernel: [ 250.063171] Clock Event Device: pit Oct 8 13:13:15 denkblock kernel: [ 250.063175] max_delta_ns: 27461866 Oct 8 13:13:15 denkblock kernel: [ 250.063177] min_delta_ns: 12571 Oct 8 13:13:15 denkblock kernel: [ 250.063180] mult: 5124677 Oct 8 13:13:15 denkblock kernel: [ 250.063183] shift: 32 Oct 8 13:13:15 denkblock kernel: [ 250.063185] mode: 3 Oct 8 13:13:15 denkblock kernel: [ 250.063188] next_event: 9223372036854775807 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063191] set_next_event: pit_next_event Oct 8 13:13:15 denkblock kernel: [ 250.063198] set_mode: init_pit_timer Oct 8 13:13:15 denkblock kernel: [ 250.063203] event_handler: tick_handle_oneshot_broadcast Oct 8 13:13:15 denkblock kernel: [ 250.063209] tick_broadcast_mask: 00000001 Oct 8 13:13:15 denkblock kernel: [ 250.063212] tick_broadcast_oneshot_mask: 00000000 Oct 8 13:13:15 denkblock kernel: [ 250.063215] Oct 8 13:13:15 denkblock kernel: [ 250.063216] Oct 8 13:13:15 denkblock kernel: [ 250.063218] Tick Device: mode: 1 Oct 8 13:13:15 denkblock kernel: [ 250.063221] Clock Event Device: lapic Oct 8 13:13:15 denkblock kernel: [ 250.063224] max_delta_ns: 1346509690 Oct 8 13:13:15 denkblock kernel: [ 250.063227] min_delta_ns: 2407 Oct 8 13:13:15 denkblock kernel: [ 250.063230] mult: 26757173 Oct 8 13:13:15 denkblock kernel: [ 250.063232] shift: 32 Oct 8 13:13:15 denkblock kernel: [ 250.063235] mode: 3 Oct 8 13:13:15 denkblock kernel: [ 250.063238] next_event: 250064208152 nsecs Oct 8 13:13:15 denkblock kernel: [ 250.063240] set_next_event: lapic_next_event Oct 8 13:13:15 denkblock kernel: [ 250.063246] set_mode: lapic_timer_setup Oct 8 13:13:15 denkblock kernel: [ 250.063250] event_handler: hrtimer_interrupt Oct 8 13:13:15 denkblock kernel: [ 250.063256] Oct 8 13:13:20 denkblock kernel: [ 255.421884] ath0: deauthenticating by local choice (reason=3) Oct 8 13:13:27 denkblock kernel: [ 262.555222] tstm: module unloaded. --8<---------------dmesg---------------end--------------->8--- ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-08 11:39 ` Elias Oltmanns @ 2008-10-08 21:14 ` Thomas Gleixner 2008-10-09 11:15 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-08 21:14 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Wed, 8 Oct 2008, Elias Oltmanns wrote: > Elias Oltmanns <eo@nebensachen.de> wrote: > > Thomas Gleixner <tglx@linutronix.de> wrote: > [...] > >> Some more questions: > >> > >> Does this happen with any on the combinations of highres/nohz > >> enabled/disabled ? > > > > From my tests in the past it would appear that NO_HZ enabled is the most > > important option to trigger the problem speedily. HIGHRES_TIMERS didn't > > seem to make much difference and I am quite sure that I observed this > > issue with NO_HZ disabled too, but very rarely. I'll keep testing and > > reporting. Meanwhile, ... > > As it turns out, it is all a bit different: Yesterday, I tried for quite > some time to reproduce the problem on a system with both, NO_HZ and > HIGH_RES_TIMERS disabled, but in vain. All other combinations trigger > the described problem, so I have appended the requested data. There is > one more odd thing: with NO_HZ disabled and HIGH_RES_TIMERS enabled, I > cannot reliably associate with the AP (WPA encrypted). Still, the timer > issue remains as you can see below and I rather suspect that this is a > separate issue. Hmm, highres=off, nohz=off has one significant difference: jiffies are incremented by the timer interrupt and not derived from ktime. I'm twisting my brain to get to the root cause of this. There is no significant deviation between jiffies and ktime in the debug output, but I noticed that you run with HZ=100, right ? So the timeout you run is 100/50 = 2. I would have a reasonable explanation if it would be 1, but I need to think about it more when I'm awake. Can you try to reproduce with HZ=250 ? I'm pretty sure it makes the problem go away. Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-08 21:14 ` Thomas Gleixner @ 2008-10-09 11:15 ` Thomas Gleixner 2008-10-10 8:33 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-09 11:15 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Wed, 8 Oct 2008, Thomas Gleixner wrote: > There is no significant deviation between jiffies and ktime in the > debug output, but I noticed that you run with HZ=100, right ? So the > timeout you run is 100/50 = 2. I would have a reasonable explanation > if it would be 1, but I need to think about it more when I'm awake. I think I know what happens. Can you please apply the following debug patch and provide the output? Thanks, tglx diff --git a/include/linux/tick.h b/include/linux/tick.h index 8cf8cfe..422b5f4 100644 --- a/include/linux/tick.h +++ b/include/linux/tick.h @@ -64,6 +64,9 @@ struct tick_sched { unsigned long last_jiffies; unsigned long next_jiffies; ktime_t idle_expires; + ktime_t last_events0; + ktime_t last_events1; + ktime_t last_events2; }; extern void __init tick_init(void); diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c index cb02324..ca7f38a 100644 --- a/kernel/time/tick-sched.c +++ b/kernel/time/tick-sched.c @@ -464,6 +464,10 @@ static void tick_nohz_handler(struct clock_event_device *dev) dev->next_event.tv64 = KTIME_MAX; + ts->last_events0 = ts->last_events1; + ts->last_events1 = ts->last_events2; + ts->last_events2 = now; + /* * Check if the do_timer duty was dropped. We don't care about * concurrency: This happens only when the cpu in charge went @@ -565,6 +569,10 @@ static enum hrtimer_restart tick_sched_timer(struct hrtimer *timer) ktime_t now = ktime_get(); int cpu = smp_processor_id(); + ts->last_events0 = ts->last_events1; + ts->last_events1 = ts->last_events2; + ts->last_events2 = now; + #ifdef CONFIG_NO_HZ /* * Check if the do_timer duty was dropped. We don't care about diff --git a/kernel/time/timer_list.c b/kernel/time/timer_list.c index a40e20f..a086926 100644 --- a/kernel/time/timer_list.c +++ b/kernel/time/timer_list.c @@ -172,6 +172,9 @@ static void print_cpu(struct seq_file *m, int cpu, u64 now) P(last_jiffies); P(next_jiffies); P_ns(idle_expires); + P_ns(last_events0); + P_ns(last_events1); + P_ns(last_events2); SEQ_printf(m, "jiffies: %Lu\n", (unsigned long long)jiffies); } ^ permalink raw reply related [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-09 11:15 ` Thomas Gleixner @ 2008-10-10 8:33 ` Elias Oltmanns 2008-10-10 10:13 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-10 8:33 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Wed, 8 Oct 2008, Thomas Gleixner wrote: >> There is no significant deviation between jiffies and ktime in the >> debug output, but I noticed that you run with HZ=100, right ? So the >> timeout you run is 100/50 = 2. I would have a reasonable explanation >> if it would be 1, but I need to think about it more when I'm awake. > > I think I know what happens. Can you please apply the following debug > patch and provide the output? Just because I didn't quite get your meaning in your earlier email, I'd like to avoid any misunderstanding and emphasise that NO_HZZ=off + HIGH_RES=off doesn't triger the problem, whereas NO_HZ=off + HIGH_RES=on does, as does NO_HZ=on + HIGH_RES=*. As for the HZ=100 vs HZ=250 issue, it doesn't seem to make much difference. As you suggested, I've tested HZ=250 now and as you can see below, the problem remains for NO_HZ=off + HIGH_RES=on, and there still is no problem for both off (as expected). Regards, Elias # CONFIG_NO_HZ is not set CONFIG_HIGH_RES_TIMERS=y --8<---------------dmesg---------------start------------->8--- Oct 10 09:31:51 denkblock kernel: [ 109.748395] timer-test: module successfully loaded. Oct 10 09:31:58 denkblock kernel: [ 116.994178] NET: Registered protocol family 17 Oct 10 09:32:03 denkblock kernel: [ 121.611352] ath0: associated Oct 10 09:32:18 denkblock kernel: [ 136.838264] b: 136.838234395 n: 136.838258980 e: 4294926505 j: 4294926505 Oct 10 09:32:18 denkblock kernel: [ 136.838279] Timer List Version: v0.3 Oct 10 09:32:18 denkblock kernel: [ 136.838281] HRTIMER_MAX_CLOCK_BASES: 2 Oct 10 09:32:18 denkblock kernel: [ 136.838284] now at 136838278535 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838287] Oct 10 09:32:18 denkblock kernel: [ 136.838288] cpu: 0 Oct 10 09:32:18 denkblock kernel: [ 136.838290] clock 0: Oct 10 09:32:18 denkblock kernel: [ 136.838292] .index: 0 Oct 10 09:32:18 denkblock kernel: [ 136.838294] .resolution: 1 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838296] .get_time: ktime_get_real Oct 10 09:32:18 denkblock kernel: [ 136.838306] .offset: 1223623801823575591 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838308] active timers: Oct 10 09:32:18 denkblock kernel: [ 136.838311] clock 1: Oct 10 09:32:18 denkblock kernel: [ 136.838313] .index: 1 Oct 10 09:32:18 denkblock kernel: [ 136.838315] .resolution: 1 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838317] .get_time: ktime_get Oct 10 09:32:18 denkblock kernel: [ 136.838321] .offset: 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838323] active timers: Oct 10 09:32:18 denkblock kernel: [ 136.838325] #0: <c02e4f18>, tick_sched_timer, S:01, tick_setup_sched_timer, init/355 Oct 10 09:32:18 denkblock kernel: [ 136.838346] # expires at 136840000000 nsecs [in 1721465 nsecs] Oct 10 09:32:18 denkblock kernel: [ 136.838349] #1: <c02e4f18>, hrtick, S:01, hrtick_start_fair, swapper/0 Oct 10 09:32:18 denkblock kernel: [ 136.838360] # expires at 136846115010 nsecs [in 7836475 nsecs] Oct 10 09:32:18 denkblock kernel: [ 136.838364] #2: <c02e4f18>, hrtimer_wakeup, S:01, do_nanosleep, tail/2452 Oct 10 09:32:18 denkblock kernel: [ 136.838375] # expires at 137670518234 nsecs [in 832239699 nsecs] Oct 10 09:32:18 denkblock kernel: [ 136.838378] #3: <c02e4f18>, it_real_fn, S:01, do_setitimer, syslogd/2356 Oct 10 09:32:18 denkblock kernel: [ 136.838391] # expires at 149813093733 nsecs [in 12974815198 nsecs] Oct 10 09:32:18 denkblock kernel: [ 136.838395] .expires_next : 136840000000 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838398] .hres_active : 1 Oct 10 09:32:18 denkblock kernel: [ 136.838400] .nr_events : 34337 Oct 10 09:32:18 denkblock kernel: [ 136.838403] .nohz_mode : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838405] .idle_tick : 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838408] .tick_stopped : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838410] .idle_jiffies : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838412] .idle_calls : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838415] .idle_sleeps : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838417] .idle_entrytime : 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838419] .idle_waketime : 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838422] .idle_exittime : 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838424] .idle_sleeptime : 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838427] .last_jiffies : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838429] .next_jiffies : 0 Oct 10 09:32:18 denkblock kernel: [ 136.838431] .idle_expires : 0 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838434] .last_events0 : 136812009783 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838437] .last_events1 : 136816009783 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838440] .last_events2 : 136838253113 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838443] jiffies: 4294926505 Oct 10 09:32:18 denkblock kernel: [ 136.838445] Oct 10 09:32:18 denkblock kernel: [ 136.838446] Oct 10 09:32:18 denkblock kernel: [ 136.838448] Tick Device: mode: 1 Oct 10 09:32:18 denkblock kernel: [ 136.838450] Clock Event Device: pit Oct 10 09:32:18 denkblock kernel: [ 136.838454] max_delta_ns: 27461866 Oct 10 09:32:18 denkblock kernel: [ 136.838456] min_delta_ns: 12571 Oct 10 09:32:18 denkblock kernel: [ 136.838459] mult: 5124677 Oct 10 09:32:18 denkblock kernel: [ 136.838461] shift: 32 Oct 10 09:32:18 denkblock kernel: [ 136.838463] mode: 3 Oct 10 09:32:18 denkblock kernel: [ 136.838466] next_event: 136840000000 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838468] set_next_event: pit_next_event Oct 10 09:32:18 denkblock kernel: [ 136.838475] set_mode: init_pit_timer Oct 10 09:32:18 denkblock kernel: [ 136.838479] event_handler: tick_handle_oneshot_broadcast Oct 10 09:32:18 denkblock kernel: [ 136.838484] tick_broadcast_mask: 00000001 Oct 10 09:32:18 denkblock kernel: [ 136.838487] tick_broadcast_oneshot_mask: 00000001 Oct 10 09:32:18 denkblock kernel: [ 136.838489] Oct 10 09:32:18 denkblock kernel: [ 136.838491] Oct 10 09:32:18 denkblock kernel: [ 136.838492] Tick Device: mode: 1 Oct 10 09:32:18 denkblock kernel: [ 136.838495] Clock Event Device: lapic Oct 10 09:32:18 denkblock kernel: [ 136.838498] max_delta_ns: 1346535456 Oct 10 09:32:18 denkblock kernel: [ 136.838500] min_delta_ns: 2407 Oct 10 09:32:18 denkblock kernel: [ 136.838503] mult: 26756661 Oct 10 09:32:18 denkblock kernel: [ 136.838505] shift: 32 Oct 10 09:32:18 denkblock kernel: [ 136.838507] mode: 1 Oct 10 09:32:18 denkblock kernel: [ 136.838510] next_event: 136840000000 nsecs Oct 10 09:32:18 denkblock kernel: [ 136.838512] set_next_event: lapic_next_event Oct 10 09:32:18 denkblock kernel: [ 136.838517] set_mode: lapic_timer_setup Oct 10 09:32:18 denkblock kernel: [ 136.838520] event_handler: hrtimer_interrupt Oct 10 09:32:18 denkblock kernel: [ 136.838524] Oct 10 09:32:28 denkblock kernel: [ 146.839547] b: 146.839519211 n: 146.839541561 e: 4294929005 j: 4294929005 Oct 10 09:32:28 denkblock kernel: [ 146.839555] Timer List Version: v0.3 Oct 10 09:32:28 denkblock kernel: [ 146.839557] HRTIMER_MAX_CLOCK_BASES: 2 Oct 10 09:32:28 denkblock kernel: [ 146.839560] now at 146839554691 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839563] Oct 10 09:32:28 denkblock kernel: [ 146.839564] cpu: 0 Oct 10 09:32:28 denkblock kernel: [ 146.839566] clock 0: Oct 10 09:32:28 denkblock kernel: [ 146.839568] .index: 0 Oct 10 09:32:28 denkblock kernel: [ 146.839570] .resolution: 1 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839572] .get_time: ktime_get_real Oct 10 09:32:28 denkblock kernel: [ 146.839583] .offset: 1223623801823575591 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839585] active timers: Oct 10 09:32:28 denkblock kernel: [ 146.839588] clock 1: Oct 10 09:32:28 denkblock kernel: [ 146.839590] .index: 1 Oct 10 09:32:28 denkblock kernel: [ 146.839592] .resolution: 1 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839594] .get_time: ktime_get Oct 10 09:32:28 denkblock kernel: [ 146.839598] .offset: 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839600] active timers: Oct 10 09:32:28 denkblock kernel: [ 146.839602] #0: <c02e4f18>, tick_sched_timer, S:01, tick_setup_sched_timer, init/355 Oct 10 09:32:28 denkblock kernel: [ 146.839622] # expires at 146840000000 nsecs [in 445309 nsecs] Oct 10 09:32:28 denkblock kernel: [ 146.839626] #1: <c02e4f18>, hrtick, S:01, hrtick_start_fair, swapper/0 Oct 10 09:32:28 denkblock kernel: [ 146.839637] # expires at 146852790351 nsecs [in 13235660 nsecs] Oct 10 09:32:28 denkblock kernel: [ 146.839640] #2: <c02e4f18>, hrtimer_wakeup, S:01, do_nanosleep, tail/2452 Oct 10 09:32:28 denkblock kernel: [ 146.839652] # expires at 147679722871 nsecs [in 840168180 nsecs] Oct 10 09:32:28 denkblock kernel: [ 146.839655] #3: <c02e4f18>, it_real_fn, S:01, do_setitimer, syslogd/2356 Oct 10 09:32:28 denkblock kernel: [ 146.839667] # expires at 149813093733 nsecs [in 2973539042 nsecs] Oct 10 09:32:28 denkblock kernel: [ 146.839671] .expires_next : 146840000000 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839674] .hres_active : 1 Oct 10 09:32:28 denkblock kernel: [ 146.839677] .nr_events : 36843 Oct 10 09:32:28 denkblock kernel: [ 146.839679] .nohz_mode : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839681] .idle_tick : 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839684] .tick_stopped : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839686] .idle_jiffies : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839688] .idle_calls : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839691] .idle_sleeps : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839693] .idle_entrytime : 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839695] .idle_waketime : 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839698] .idle_exittime : 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839700] .idle_sleeptime : 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839703] .last_jiffies : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839705] .next_jiffies : 0 Oct 10 09:32:28 denkblock kernel: [ 146.839707] .idle_expires : 0 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839710] .last_events0 : 146812009783 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839713] .last_events1 : 146816009783 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839716] .last_events2 : 146839535135 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839719] jiffies: 4294929005 Oct 10 09:32:28 denkblock kernel: [ 146.839721] Oct 10 09:32:28 denkblock kernel: [ 146.839722] Oct 10 09:32:28 denkblock kernel: [ 146.839724] Tick Device: mode: 1 Oct 10 09:32:28 denkblock kernel: [ 146.839726] Clock Event Device: pit Oct 10 09:32:28 denkblock kernel: [ 146.839730] max_delta_ns: 27461866 Oct 10 09:32:28 denkblock kernel: [ 146.839732] min_delta_ns: 12571 Oct 10 09:32:28 denkblock kernel: [ 146.839735] mult: 5124677 Oct 10 09:32:28 denkblock kernel: [ 146.839737] shift: 32 Oct 10 09:32:28 denkblock kernel: [ 146.839739] mode: 3 Oct 10 09:32:28 denkblock kernel: [ 146.839742] next_event: 9223372036854775807 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839745] set_next_event: pit_next_event Oct 10 09:32:28 denkblock kernel: [ 146.839752] set_mode: init_pit_timer Oct 10 09:32:28 denkblock kernel: [ 146.839757] event_handler: tick_handle_oneshot_broadcast Oct 10 09:32:28 denkblock kernel: [ 146.839762] tick_broadcast_mask: 00000001 Oct 10 09:32:28 denkblock kernel: [ 146.839764] tick_broadcast_oneshot_mask: 00000000 Oct 10 09:32:28 denkblock kernel: [ 146.839767] Oct 10 09:32:28 denkblock kernel: [ 146.839768] Oct 10 09:32:28 denkblock kernel: [ 146.839770] Tick Device: mode: 1 Oct 10 09:32:28 denkblock kernel: [ 146.839772] Clock Event Device: lapic Oct 10 09:32:28 denkblock kernel: [ 146.839775] max_delta_ns: 1346535456 Oct 10 09:32:28 denkblock kernel: [ 146.839778] min_delta_ns: 2407 Oct 10 09:32:28 denkblock kernel: [ 146.839780] mult: 26756661 Oct 10 09:32:28 denkblock kernel: [ 146.839783] shift: 32 Oct 10 09:32:28 denkblock kernel: [ 146.839785] mode: 3 Oct 10 09:32:28 denkblock kernel: [ 146.839787] next_event: 146840000000 nsecs Oct 10 09:32:28 denkblock kernel: [ 146.839790] set_next_event: lapic_next_event Oct 10 09:32:28 denkblock kernel: [ 146.839794] set_mode: lapic_timer_setup Oct 10 09:32:28 denkblock kernel: [ 146.839798] event_handler: hrtimer_interrupt Oct 10 09:32:28 denkblock kernel: [ 146.839802] Oct 10 09:32:38 denkblock kernel: [ 156.838299] b: 156.838280491 n: 156.838293621 e: 4294931505 j: 4294931505 Oct 10 09:32:38 denkblock kernel: [ 156.838305] Timer List Version: v0.3 Oct 10 09:32:38 denkblock kernel: [ 156.838308] HRTIMER_MAX_CLOCK_BASES: 2 Oct 10 09:32:38 denkblock kernel: [ 156.838311] now at 156838305355 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838313] Oct 10 09:32:38 denkblock kernel: [ 156.838315] cpu: 0 Oct 10 09:32:38 denkblock kernel: [ 156.838317] clock 0: Oct 10 09:32:38 denkblock kernel: [ 156.838319] .index: 0 Oct 10 09:32:38 denkblock kernel: [ 156.838321] .resolution: 1 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838323] .get_time: ktime_get_real Oct 10 09:32:38 denkblock kernel: [ 156.838333] .offset: 1223623801823575591 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838336] active timers: Oct 10 09:32:38 denkblock kernel: [ 156.838338] clock 1: Oct 10 09:32:38 denkblock kernel: [ 156.838340] .index: 1 Oct 10 09:32:38 denkblock kernel: [ 156.838342] .resolution: 1 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838344] .get_time: ktime_get Oct 10 09:32:38 denkblock kernel: [ 156.838348] .offset: 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838350] active timers: Oct 10 09:32:38 denkblock kernel: [ 156.838352] #0: <c02e4f18>, tick_sched_timer, S:01, tick_setup_sched_timer, init/355 Oct 10 09:32:38 denkblock kernel: [ 156.838373] # expires at 156840000000 nsecs [in 1694645 nsecs] Oct 10 09:32:38 denkblock kernel: [ 156.838376] #1: <c02e4f18>, it_real_fn, S:01, do_setitimer, syslogd/2356 Oct 10 09:32:38 denkblock kernel: [ 156.838390] # expires at 179813134800 nsecs [in 22974829445 nsecs] Oct 10 09:32:38 denkblock kernel: [ 156.838394] .expires_next : 156840000000 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838397] .hres_active : 1 Oct 10 09:32:38 denkblock kernel: [ 156.838399] .nr_events : 39345 Oct 10 09:32:38 denkblock kernel: [ 156.838402] .nohz_mode : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838404] .idle_tick : 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838407] .tick_stopped : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838409] .idle_jiffies : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838411] .idle_calls : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838413] .idle_sleeps : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838416] .idle_entrytime : 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838418] .idle_waketime : 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838420] .idle_exittime : 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838423] .idle_sleeptime : 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838425] .last_jiffies : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838428] .next_jiffies : 0 Oct 10 09:32:38 denkblock kernel: [ 156.838430] .idle_expires : 0 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838433] .last_events0 : 156812009224 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838436] .last_events1 : 156816010062 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838439] .last_events2 : 156838287755 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838441] jiffies: 4294931505 Oct 10 09:32:38 denkblock kernel: [ 156.838443] Oct 10 09:32:38 denkblock kernel: [ 156.838445] Oct 10 09:32:38 denkblock kernel: [ 156.838447] Tick Device: mode: 1 Oct 10 09:32:38 denkblock kernel: [ 156.838449] Clock Event Device: pit Oct 10 09:32:38 denkblock kernel: [ 156.838452] max_delta_ns: 27461866 Oct 10 09:32:38 denkblock kernel: [ 156.838455] min_delta_ns: 12571 Oct 10 09:32:38 denkblock kernel: [ 156.838457] mult: 5124677 Oct 10 09:32:38 denkblock kernel: [ 156.838460] shift: 32 Oct 10 09:32:38 denkblock kernel: [ 156.838462] mode: 3 Oct 10 09:32:38 denkblock kernel: [ 156.838465] next_event: 9223372036854775807 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838467] set_next_event: pit_next_event Oct 10 09:32:38 denkblock kernel: [ 156.838474] set_mode: init_pit_timer Oct 10 09:32:38 denkblock kernel: [ 156.838479] event_handler: tick_handle_oneshot_broadcast Oct 10 09:32:38 denkblock kernel: [ 156.838484] tick_broadcast_mask: 00000001 Oct 10 09:32:38 denkblock kernel: [ 156.838486] tick_broadcast_oneshot_mask: 00000000 Oct 10 09:32:38 denkblock kernel: [ 156.838489] Oct 10 09:32:38 denkblock kernel: [ 156.838490] Oct 10 09:32:38 denkblock kernel: [ 156.838492] Tick Device: mode: 1 Oct 10 09:32:38 denkblock kernel: [ 156.838494] Clock Event Device: lapic Oct 10 09:32:38 denkblock kernel: [ 156.838497] max_delta_ns: 1346535456 Oct 10 09:32:38 denkblock kernel: [ 156.838500] min_delta_ns: 2407 Oct 10 09:32:38 denkblock kernel: [ 156.838502] mult: 26756661 Oct 10 09:32:38 denkblock kernel: [ 156.838505] shift: 32 Oct 10 09:32:38 denkblock kernel: [ 156.838507] mode: 3 Oct 10 09:32:38 denkblock kernel: [ 156.838509] next_event: 156840000000 nsecs Oct 10 09:32:38 denkblock kernel: [ 156.838512] set_next_event: lapic_next_event Oct 10 09:32:38 denkblock kernel: [ 156.838516] set_mode: lapic_timer_setup Oct 10 09:32:38 denkblock kernel: [ 156.838520] event_handler: hrtimer_interrupt Oct 10 09:32:38 denkblock kernel: [ 156.838524] Oct 10 09:32:40 denkblock kernel: [ 158.720450] ath0: deauthenticating by local choice (reason=3) Oct 10 09:32:49 denkblock kernel: [ 167.195292] tstm: module unloaded. --8<---------------dmesg---------------end--------------->8--- > > Thanks, > > tglx > > diff --git a/include/linux/tick.h b/include/linux/tick.h > index 8cf8cfe..422b5f4 100644 > --- a/include/linux/tick.h > +++ b/include/linux/tick.h > @@ -64,6 +64,9 @@ struct tick_sched { > unsigned long last_jiffies; > unsigned long next_jiffies; > ktime_t idle_expires; > + ktime_t last_events0; > + ktime_t last_events1; > + ktime_t last_events2; > }; > > extern void __init tick_init(void); > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c > index cb02324..ca7f38a 100644 > --- a/kernel/time/tick-sched.c > +++ b/kernel/time/tick-sched.c > @@ -464,6 +464,10 @@ static void tick_nohz_handler(struct clock_event_device *dev) > > dev->next_event.tv64 = KTIME_MAX; > > + ts->last_events0 = ts->last_events1; > + ts->last_events1 = ts->last_events2; > + ts->last_events2 = now; > + > /* > * Check if the do_timer duty was dropped. We don't care about > * concurrency: This happens only when the cpu in charge went > @@ -565,6 +569,10 @@ static enum hrtimer_restart tick_sched_timer(struct hrtimer *timer) > ktime_t now = ktime_get(); > int cpu = smp_processor_id(); > > + ts->last_events0 = ts->last_events1; > + ts->last_events1 = ts->last_events2; > + ts->last_events2 = now; > + > #ifdef CONFIG_NO_HZ > /* > * Check if the do_timer duty was dropped. We don't care about > diff --git a/kernel/time/timer_list.c b/kernel/time/timer_list.c > index a40e20f..a086926 100644 > --- a/kernel/time/timer_list.c > +++ b/kernel/time/timer_list.c > @@ -172,6 +172,9 @@ static void print_cpu(struct seq_file *m, int cpu, u64 now) > P(last_jiffies); > P(next_jiffies); > P_ns(idle_expires); > + P_ns(last_events0); > + P_ns(last_events1); > + P_ns(last_events2); > SEQ_printf(m, "jiffies: %Lu\n", > (unsigned long long)jiffies); > } ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 8:33 ` Elias Oltmanns @ 2008-10-10 10:13 ` Thomas Gleixner 2008-10-10 11:50 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-10 10:13 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Fri, 10 Oct 2008, Elias Oltmanns wrote: > Thomas Gleixner <tglx@linutronix.de> wrote: > > On Wed, 8 Oct 2008, Thomas Gleixner wrote: > >> There is no significant deviation between jiffies and ktime in the > >> debug output, but I noticed that you run with HZ=100, right ? So the > >> timeout you run is 100/50 = 2. I would have a reasonable explanation > >> if it would be 1, but I need to think about it more when I'm awake. > > > > I think I know what happens. Can you please apply the following debug > > patch and provide the output? > > Just because I didn't quite get your meaning in your earlier email, I'd > like to avoid any misunderstanding and emphasise that NO_HZZ=off + > HIGH_RES=off doesn't triger the problem, whereas NO_HZ=off + HIGH_RES=on > does, as does NO_HZ=on + HIGH_RES=*. As for the HZ=100 vs HZ=250 issue, > it doesn't seem to make much difference. As you suggested, I've tested > HZ=250 now and as you can see below, the problem remains for NO_HZ=off + > HIGH_RES=on, and there still is no problem for both off (as expected). Yeah, the HZ=250 was a tired wild guess. As I said "I need to think about it more when I'm awake" :) So lets analyse the new data: > [ 121.611352] ath0: associated > [ 136.838264] b: 136.838234395 n: 136.838258980 e: 4294926505 j: 4294926505 > [ 136.838325] #0: <c02e4f18>, tick_sched_timer, S:01, tick_setup_sched_timer, init/355 > [ 136.838346] # expires at 136840000000 nsecs [in 1721465 nsecs] tick_sched_timer is the one which updates jiffies. next expiry: 136.840 So at HZ=250 we expect that it expired at: 136.836, 136.832, 136.828, 136.824, 136.820, 136.816, 136.812 so we would have expected to see .last_events0 136.828 .last_events1 136.832 .last_events2 136.836 but we get: > [ 136.838434] .last_events0 : 136812009783 nsecs > [ 136.838437] .last_events1 : 136816009783 nsecs > [ 136.838440] .last_events2 : 136838253113 nsecs The last event was 22.24333 ms (4 ticks) after the previous one. b: 136.838234395 is right before .last_event2 136.838253113 and n: 136.838258980 is right after that. That explains your problem quite well :) So now the question is why was the interrupt blocked for that time. Can you please add the following debug patch as well ? Thanks, tglx --- diff --git a/kernel/softirq.c b/kernel/softirq.c index c506f26..cf29022 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -206,6 +206,11 @@ restart: do { if (pending & 1) { h->action(h); + if (unlikely(irqs_disabled())) { + printk(KERN_ERR "softirq %d returned with " + "irqs disabled\n", (int)(softirq_vec - h)); + local_irq_enable(); + } rcu_bh_qsctr_inc(cpu); } h++; ^ permalink raw reply related [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 10:13 ` Thomas Gleixner @ 2008-10-10 11:50 ` Elias Oltmanns 2008-10-10 12:34 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-10 11:50 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Fri, 10 Oct 2008, Elias Oltmanns wrote: >> Thomas Gleixner <tglx@linutronix.de> wrote: > >> > On Wed, 8 Oct 2008, Thomas Gleixner wrote: >> >> There is no significant deviation between jiffies and ktime in the >> >> debug output, but I noticed that you run with HZ=100, right ? So the >> >> timeout you run is 100/50 = 2. I would have a reasonable explanation >> >> if it would be 1, but I need to think about it more when I'm awake. >> > >> > I think I know what happens. Can you please apply the following debug >> > patch and provide the output? >> >> Just because I didn't quite get your meaning in your earlier email, I'd >> like to avoid any misunderstanding and emphasise that NO_HZZ=off + >> HIGH_RES=off doesn't triger the problem, whereas NO_HZ=off + HIGH_RES=on >> does, as does NO_HZ=on + HIGH_RES=*. As for the HZ=100 vs HZ=250 issue, >> it doesn't seem to make much difference. As you suggested, I've tested >> HZ=250 now and as you can see below, the problem remains for NO_HZ=off + >> HIGH_RES=on, and there still is no problem for both off (as expected). > > Yeah, the HZ=250 was a tired wild guess. As I said "I need to think > about it more when I'm awake" :) > > So lets analyse the new data: > >> [ 121.611352] ath0: associated > >> [ 136.838264] b: 136.838234395 n: 136.838258980 e: 4294926505 j: 4294926505 > >> [ 136.838325] #0: <c02e4f18>, tick_sched_timer, S:01, tick_setup_sched_timer, init/355 >> [ 136.838346] # expires at 136840000000 nsecs [in 1721465 nsecs] > > tick_sched_timer is the one which updates jiffies. next expiry: 136.840 > > So at HZ=250 we expect that it expired at: > > 136.836, 136.832, 136.828, 136.824, 136.820, 136.816, 136.812 > > so we would have expected to see > > .last_events0 136.828 > .last_events1 136.832 > .last_events2 136.836 > > but we get: > >> [ 136.838434] .last_events0 : 136812009783 nsecs >> [ 136.838437] .last_events1 : 136816009783 nsecs >> [ 136.838440] .last_events2 : 136838253113 nsecs > > The last event was 22.24333 ms (4 ticks) after the previous one. > > b: 136.838234395 > is right before > .last_event2 136.838253113 > and > n: 136.838258980 > is right after that. > > That explains your problem quite well :) > > So now the question is why was the interrupt blocked for that time. > > Can you please add the following debug patch as well ? That printk() has not been hit, I'm afraid. The output of sysrq_timer_list_show() looks much the same but there is no message about softirqs. Just for the record, I've switched to 2.6.27 because I'm debugging something else at the same time, but it doesn't make any difference. Now, here is another question: There are various snippets like the following in the ath5k driver: /* Wait until the noise floor is calibrated and read the value */ for (i = 20; i > 0; i--) { mdelay(1); noise_floor = ath5k_hw_reg_read(ah, AR5K_PHY_NF); noise_floor = AR5K_PHY_NF_RVAL(noise_floor); if (noise_floor & AR5K_PHY_NF_ACTIVE) { noise_floor = AR5K_PHY_NF_AVAL(noise_floor); if (noise_floor <= AR5K_TUNE_NOISE_FLOOR) break; } } This particular one is in drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration() which is called from ath5k_calibrate(), the callback executed every ten seconds in softirq context. Could this have anything to do with our problem? Perhaps I should insert some printks in this callback and check how much time is spent executing various pieces of code. Unless you have a better suggestion, I'll do that later. Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 11:50 ` Elias Oltmanns @ 2008-10-10 12:34 ` Thomas Gleixner 2008-10-10 12:59 ` Elias Oltmanns ` (2 more replies) 0 siblings, 3 replies; 27+ messages in thread From: Thomas Gleixner @ 2008-10-10 12:34 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Fri, 10 Oct 2008, Elias Oltmanns wrote: > That printk() has not been hit, I'm afraid. The output of > sysrq_timer_list_show() looks much the same but there is no message > about softirqs. Just for the record, I've switched to 2.6.27 because I'm > debugging something else at the same time, but it doesn't make any > difference. > > Now, here is another question: There are various snippets like the > following in the ath5k driver: > > /* Wait until the noise floor is calibrated and read the value */ > for (i = 20; i > 0; i--) { > mdelay(1); Uurgh. That's broken. mdelay sleeps so this should not be called in softirq context. > noise_floor = ath5k_hw_reg_read(ah, AR5K_PHY_NF); > noise_floor = AR5K_PHY_NF_RVAL(noise_floor); > if (noise_floor & AR5K_PHY_NF_ACTIVE) { > noise_floor = AR5K_PHY_NF_AVAL(noise_floor); > > if (noise_floor <= AR5K_TUNE_NOISE_FLOOR) > break; > } > } > > This particular one is in > drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration() > which is called from ath5k_calibrate(), the callback executed every ten > seconds in softirq context. Could this have anything to do with our That makes sense. The timer expires early events are multiples of 10s apart. Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 12:34 ` Thomas Gleixner @ 2008-10-10 12:59 ` Elias Oltmanns 2008-10-10 21:32 ` Christoph Hellwig 2008-10-10 19:24 ` Nick Kossifidis 2008-10-11 9:54 ` Thomas Gleixner 2 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-10 12:59 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Fri, 10 Oct 2008, Elias Oltmanns wrote: >> That printk() has not been hit, I'm afraid. The output of > >> sysrq_timer_list_show() looks much the same but there is no message >> about softirqs. Just for the record, I've switched to 2.6.27 because I'm >> debugging something else at the same time, but it doesn't make any >> difference. >> >> Now, here is another question: There are various snippets like the >> following in the ath5k driver: >> >> /* Wait until the noise floor is calibrated and read the value */ >> for (i = 20; i > 0; i--) { >> mdelay(1); > > Uurgh. That's broken. mdelay sleeps so this should not be called in > softirq context. That was my first thought when I discovered this. However, from what I read on the web, I somehow got the impression that [um]delay() was alright as opposed to msleep(). What exactly is the difference then? Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 12:59 ` Elias Oltmanns @ 2008-10-10 21:32 ` Christoph Hellwig 2008-10-11 9:55 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Christoph Hellwig @ 2008-10-10 21:32 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Thomas Gleixner, Jiri Slaby, linux-wireless On Fri, Oct 10, 2008 at 02:59:28PM +0200, Elias Oltmanns wrote: > That was my first thought when I discovered this. However, from what I > read on the web, I somehow got the impression that [um]delay() was > alright as opposed to msleep(). What exactly is the difference then? Yes, only msleep() sleeps, mdelay spins. ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 21:32 ` Christoph Hellwig @ 2008-10-11 9:55 ` Thomas Gleixner 0 siblings, 0 replies; 27+ messages in thread From: Thomas Gleixner @ 2008-10-11 9:55 UTC (permalink / raw) To: Christoph Hellwig; +Cc: Elias Oltmanns, Jiri Slaby, linux-wireless On Fri, 10 Oct 2008, Christoph Hellwig wrote: > On Fri, Oct 10, 2008 at 02:59:28PM +0200, Elias Oltmanns wrote: > > That was my first thought when I discovered this. However, from what I > > read on the web, I somehow got the impression that [um]delay() was > > alright as opposed to msleep(). What exactly is the difference then? > > Yes, only msleep() sleeps, mdelay spins. Opps, right. ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 12:34 ` Thomas Gleixner 2008-10-10 12:59 ` Elias Oltmanns @ 2008-10-10 19:24 ` Nick Kossifidis 2008-10-11 9:54 ` Thomas Gleixner 2 siblings, 0 replies; 27+ messages in thread From: Nick Kossifidis @ 2008-10-10 19:24 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Elias Oltmanns, Jiri Slaby, linux-wireless 2008/10/10 Thomas Gleixner <tglx@linutronix.de>: > On Fri, 10 Oct 2008, Elias Oltmanns wrote: >> That printk() has not been hit, I'm afraid. The output of >> sysrq_timer_list_show() looks much the same but there is no message >> about softirqs. Just for the record, I've switched to 2.6.27 because I'm >> debugging something else at the same time, but it doesn't make any >> difference. >> >> Now, here is another question: There are various snippets like the >> following in the ath5k driver: >> >> /* Wait until the noise floor is calibrated and read the value */ >> for (i = 20; i > 0; i--) { >> mdelay(1); > > Uurgh. That's broken. mdelay sleeps so this should not be called in > softirq context. > >> noise_floor = ath5k_hw_reg_read(ah, AR5K_PHY_NF); >> noise_floor = AR5K_PHY_NF_RVAL(noise_floor); >> if (noise_floor & AR5K_PHY_NF_ACTIVE) { >> noise_floor = AR5K_PHY_NF_AVAL(noise_floor); >> >> if (noise_floor <= AR5K_TUNE_NOISE_FLOOR) >> break; >> } >> } >> >> This particular one is in >> drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration() >> which is called from ath5k_calibrate(), the callback executed every ten >> seconds in softirq context. Could this have anything to do with our > > That makes sense. The timer expires early events are multiples of 10s > apart. > > Thanks, > > tglx What should we use then ? udelay(1000) ? -- GPG ID: 0xD21DB2DB As you read this post global entropy rises. Have Fun ;-) Nick ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-10 12:34 ` Thomas Gleixner 2008-10-10 12:59 ` Elias Oltmanns 2008-10-10 19:24 ` Nick Kossifidis @ 2008-10-11 9:54 ` Thomas Gleixner 2008-10-11 20:30 ` Elias Oltmanns 2 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-11 9:54 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Fri, 10 Oct 2008, Thomas Gleixner wrote: > On Fri, 10 Oct 2008, Elias Oltmanns wrote: > > That printk() has not been hit, I'm afraid. The output of > > sysrq_timer_list_show() looks much the same but there is no message > > about softirqs. Just for the record, I've switched to 2.6.27 because I'm > > debugging something else at the same time, but it doesn't make any > > difference. > > > > Now, here is another question: There are various snippets like the > > following in the ath5k driver: > > > > /* Wait until the noise floor is calibrated and read the value */ > > for (i = 20; i > 0; i--) { > > mdelay(1); > > Uurgh. That's broken. mdelay sleeps so this should not be called in > softirq context. > > > noise_floor = ath5k_hw_reg_read(ah, AR5K_PHY_NF); > > noise_floor = AR5K_PHY_NF_RVAL(noise_floor); > > if (noise_floor & AR5K_PHY_NF_ACTIVE) { > > noise_floor = AR5K_PHY_NF_AVAL(noise_floor); > > > > if (noise_floor <= AR5K_TUNE_NOISE_FLOOR) > > break; > > } > > } > > > > This particular one is in > > drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration() > > which is called from ath5k_calibrate(), the callback executed every ten > > seconds in softirq context. Could this have anything to do with our > > That makes sense. The timer expires early events are multiples of 10s > apart. Ok, I thought more about it and aside of the fact that the ath5k is doing something nasty, you unearthed a weakness in the broadcast code. Can you please try the following: Compile the acpi_processor module in to the kernel (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel command line. If I analysed the problem correctly this will make the jiffies problem go away. I'm working on a fix. Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-11 9:54 ` Thomas Gleixner @ 2008-10-11 20:30 ` Elias Oltmanns 2008-10-14 19:00 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-11 20:30 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Fri, 10 Oct 2008, Thomas Gleixner wrote: >> On Fri, 10 Oct 2008, Elias Oltmanns wrote: [...] >> > This particular one is in >> > drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration() >> > which is called from ath5k_calibrate(), the callback executed every ten >> > seconds in softirq context. Could this have anything to do with our >> >> That makes sense. The timer expires early events are multiples of 10s >> apart. > > Ok, I thought more about it and aside of the fact that the ath5k is > doing something nasty, you unearthed a weakness in the broadcast code. > > Can you please try the following: > > Compile the acpi_processor module in to the kernel > (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel > command line. If I analysed the problem correctly this will make the > jiffies problem go away. I'm working on a fix. Spot on, it does go away regardless whether NO_HZ or HIGH_RES are enabled or disabled. Looking forward to testing your fix ;-). Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-11 20:30 ` Elias Oltmanns @ 2008-10-14 19:00 ` Thomas Gleixner 2008-10-14 22:01 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-14 19:00 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Sat, 11 Oct 2008, Elias Oltmanns wrote: > > Compile the acpi_processor module in to the kernel > > (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel > > command line. If I analysed the problem correctly this will make the > > jiffies problem go away. I'm working on a fix. > > Spot on, it does go away regardless whether NO_HZ or HIGH_RES are > enabled or disabled. Looking forward to testing your fix ;-). Here you go. tglx --- diff --git a/include/linux/tick.h b/include/linux/tick.h index 98921a3..cb271ce 100644 --- a/include/linux/tick.h +++ b/include/linux/tick.h @@ -96,9 +96,11 @@ extern cpumask_t *tick_get_broadcast_oneshot_mask(void); extern void tick_clock_notify(void); extern int tick_check_oneshot_change(int allow_nohz); extern struct tick_sched *tick_get_tick_sched(int cpu); +extern void tick_check_idle(int cpu); # else static inline void tick_clock_notify(void) { } static inline int tick_check_oneshot_change(int allow_nohz) { return 0; } +static inline void tick_check_idle(int cpu) { } # endif #else /* CONFIG_GENERIC_CLOCKEVENTS */ @@ -111,21 +113,17 @@ static inline int tick_check_oneshot_change(int allow_nohz) { return 0; } # ifdef CONFIG_NO_HZ extern void tick_nohz_stop_sched_tick(int inidle); extern void tick_nohz_restart_sched_tick(void); -extern void tick_nohz_update_jiffies(void); extern ktime_t tick_nohz_get_sleep_length(void); -extern void tick_nohz_stop_idle(int cpu); extern u64 get_cpu_idle_time_us(int cpu, u64 *last_update_time); # else static inline void tick_nohz_stop_sched_tick(int inidle) { } static inline void tick_nohz_restart_sched_tick(void) { } -static inline void tick_nohz_update_jiffies(void) { } static inline ktime_t tick_nohz_get_sleep_length(void) { ktime_t len = { .tv64 = NSEC_PER_SEC/HZ }; return len; } -static inline void tick_nohz_stop_idle(int cpu) { } static inline u64 get_cpu_idle_time_us(int cpu, u64 *unused) { return -1; } # endif /* !NO_HZ */ diff --git a/kernel/softirq.c b/kernel/softirq.c index c506f26..6ad6aec 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -254,16 +254,12 @@ asmlinkage void do_softirq(void) */ void irq_enter(void) { -#ifdef CONFIG_NO_HZ int cpu = smp_processor_id(); - if (idle_cpu(cpu) && !in_interrupt()) - tick_nohz_stop_idle(cpu); -#endif - __irq_enter(); -#ifdef CONFIG_NO_HZ + if (idle_cpu(cpu)) - tick_nohz_update_jiffies(); -#endif + tick_check_idle(cpu); + + __irq_enter(); } #ifdef __ARCH_IRQ_EXIT_IRQS_DISABLED diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c index cb01cd8..f98a1b7 100644 --- a/kernel/time/tick-broadcast.c +++ b/kernel/time/tick-broadcast.c @@ -384,6 +384,19 @@ int tick_resume_broadcast_oneshot(struct clock_event_device *bc) } /* + * Called from irq_enter() when idle was interrupted to reenable the + * per cpu device. + */ +void tick_check_oneshot_broadcast(int cpu) +{ + if (cpu_isset(cpu, tick_broadcast_oneshot_mask)) { + struct tick_device *td = &per_cpu(tick_cpu_device, cpu); + + clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT); + } +} + +/* * Handle oneshot mode broadcasting */ static void tick_handle_oneshot_broadcast(struct clock_event_device *dev) diff --git a/kernel/time/tick-internal.h b/kernel/time/tick-internal.h index 4692487..b1c05bf 100644 --- a/kernel/time/tick-internal.h +++ b/kernel/time/tick-internal.h @@ -36,6 +36,7 @@ extern void tick_broadcast_switch_to_oneshot(void); extern void tick_shutdown_broadcast_oneshot(unsigned int *cpup); extern int tick_resume_broadcast_oneshot(struct clock_event_device *bc); extern int tick_broadcast_oneshot_active(void); +extern void tick_check_oneshot_broadcast(int cpu); # else /* BROADCAST */ static inline void tick_broadcast_setup_oneshot(struct clock_event_device *bc) { @@ -45,6 +46,7 @@ static inline void tick_broadcast_oneshot_control(unsigned long reason) { } static inline void tick_broadcast_switch_to_oneshot(void) { } static inline void tick_shutdown_broadcast_oneshot(unsigned int *cpup) { } static inline int tick_broadcast_oneshot_active(void) { return 0; } +static inline void tick_check_oneshot_broadcast(int cpu) { } # endif /* !BROADCAST */ #else /* !ONESHOT */ diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c index a4d2193..d1b39e6 100644 --- a/kernel/time/tick-sched.c +++ b/kernel/time/tick-sched.c @@ -155,7 +155,7 @@ void tick_nohz_update_jiffies(void) touch_softlockup_watchdog(); } -void tick_nohz_stop_idle(int cpu) +static void tick_nohz_stop_idle(int cpu) { struct tick_sched *ts = &per_cpu(tick_cpu_sched, cpu); @@ -559,6 +559,20 @@ static inline void tick_nohz_switch_to_nohz(void) { } #endif /* NO_HZ */ /* + * Called from irq_enter to notify about the possible interruption of idle() + */ +void tick_check_idle(int cpu) +{ +#ifdef CONFIG_NO_HZ + if (!in_interrupt()) { + tick_nohz_stop_idle(cpu); + tick_nohz_update_jiffies(); + } +#endif + tick_check_oneshot_broadcast(cpu); +} + +/* * High resolution timer specific code */ #ifdef CONFIG_HIGH_RES_TIMERS ^ permalink raw reply related [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-14 19:00 ` Thomas Gleixner @ 2008-10-14 22:01 ` Elias Oltmanns 2008-10-15 8:43 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-14 22:01 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Sat, 11 Oct 2008, Elias Oltmanns wrote: >> > Compile the acpi_processor module in to the kernel > >> > (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel >> > command line. If I analysed the problem correctly this will make the >> > jiffies problem go away. I'm working on a fix. >> >> Spot on, it does go away regardless whether NO_HZ or HIGH_RES are >> enabled or disabled. Looking forward to testing your fix ;-). > > Here you go. Bad luck, I'm afraid. Your patch seems to fix the issue for NO_HZ=n + HIGH_RES=y. As soon as NO_HZ=y, however, the problem reappears. See the output below. (Still testing on 2.6.27, mind. Should I test something more up-to-date?) Regards, Elias --8<---------------dmesg---------------start------------->8--- Oct 14 22:44:25 denkblock kernel: [ 150.063028] b: 150.062655731 n: 150.063022258 e: 4294952302 j: 4294952302 Oct 14 22:44:25 denkblock kernel: [ 150.063035] Timer List Version: v0.3 Oct 14 22:44:25 denkblock kernel: [ 150.063038] HRTIMER_MAX_CLOCK_BASES: 2 Oct 14 22:44:25 denkblock kernel: [ 150.063041] now at 150063035109 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063043] Oct 14 22:44:25 denkblock kernel: [ 150.063045] cpu: 0 Oct 14 22:44:25 denkblock kernel: [ 150.063047] clock 0: Oct 14 22:44:25 denkblock kernel: [ 150.063048] .index: 0 Oct 14 22:44:25 denkblock kernel: [ 150.063051] .resolution: 10000000 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063053] .get_time: ktime_get_real Oct 14 22:44:25 denkblock kernel: [ 150.063062] active timers: Oct 14 22:44:25 denkblock kernel: [ 150.063064] clock 1: Oct 14 22:44:25 denkblock kernel: [ 150.063066] .index: 1 Oct 14 22:44:25 denkblock kernel: [ 150.063068] .resolution: 10000000 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063070] .get_time: ktime_get Oct 14 22:44:25 denkblock kernel: [ 150.063074] active timers: Oct 14 22:44:25 denkblock kernel: [ 150.063076] #0: <c02e2f14>, hrtimer_wakeup, S:01, do_nanosleep, tail/2440 Oct 14 22:44:25 denkblock kernel: [ 150.063098] # expires at 150440037040 nsecs [in 377001931 nsecs] Oct 14 22:44:25 denkblock kernel: [ 150.063102] #1: <c02e2f14>, it_real_fn, S:01, do_setitimer, syslogd/2343 Oct 14 22:44:25 denkblock kernel: [ 150.063115] # expires at 173530381509 nsecs [in 23467346400 nsecs] Oct 14 22:44:25 denkblock kernel: [ 150.063119] .nohz_mode : 1 Oct 14 22:44:25 denkblock kernel: [ 150.063121] .idle_tick : 150030000000 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063124] .tick_stopped : 0 Oct 14 22:44:25 denkblock kernel: [ 150.063126] .idle_jiffies : 4294952299 Oct 14 22:44:25 denkblock kernel: [ 150.063129] .idle_calls : 21431 Oct 14 22:44:25 denkblock kernel: [ 150.063132] .idle_sleeps : 16504 Oct 14 22:44:25 denkblock kernel: [ 150.063134] .idle_entrytime : 150063016112 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063137] .idle_waketime : 150040009551 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063140] .idle_exittime : 150062664671 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063143] .idle_sleeptime : 138813566362 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063146] .last_jiffies : 4294952302 Oct 14 22:44:25 denkblock kernel: [ 150.063148] .next_jiffies : 4294952302 Oct 14 22:44:25 denkblock kernel: [ 150.063151] .idle_expires : 150040000000 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063154] .last_events0 : 150010011037 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063157] .last_events1 : 150020010914 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063159] .last_events2 : 150040012344 nsecs Oct 14 22:44:25 denkblock kernel: [ 150.063162] jiffies: 4294952302 Oct 14 22:44:25 denkblock kernel: [ 150.063164] Oct 14 22:44:25 denkblock kernel: [ 150.063165] Oct 14 22:44:25 denkblock kernel: [ 150.063167] Tick Device: mode: 1 Oct 14 22:44:25 denkblock kernel: [ 150.063169] Clock Event Device: pit Oct 14 22:44:26 denkblock kernel: [ 150.063172] max_delta_ns: 27461866 Oct 14 22:44:26 denkblock kernel: [ 150.063175] min_delta_ns: 12571 Oct 14 22:44:26 denkblock kernel: [ 150.063177] mult: 5124677 Oct 14 22:44:26 denkblock kernel: [ 150.063179] shift: 32 Oct 14 22:44:26 denkblock kernel: [ 150.063181] mode: 3 Oct 14 22:44:26 denkblock kernel: [ 150.063184] next_event: 9223372036854775807 nsecs Oct 14 22:44:26 denkblock kernel: [ 150.063187] set_next_event: pit_next_event Oct 14 22:44:26 denkblock kernel: [ 150.063193] set_mode: init_pit_timer Oct 14 22:44:26 denkblock kernel: [ 150.063197] event_handler: tick_handle_oneshot_broadcast Oct 14 22:44:26 denkblock kernel: [ 150.063203] tick_broadcast_mask: 00000001 Oct 14 22:44:26 denkblock kernel: [ 150.063205] tick_broadcast_oneshot_mask: 00000000 Oct 14 22:44:26 denkblock kernel: [ 150.063208] Oct 14 22:44:26 denkblock kernel: [ 150.063209] Oct 14 22:44:26 denkblock kernel: [ 150.063211] Tick Device: mode: 1 Oct 14 22:44:26 denkblock kernel: [ 150.063213] Clock Event Device: lapic Oct 14 22:44:26 denkblock kernel: [ 150.063216] max_delta_ns: 1346509690 Oct 14 22:44:26 denkblock kernel: [ 150.063218] min_delta_ns: 2407 Oct 14 22:44:26 denkblock kernel: [ 150.063221] mult: 26757173 Oct 14 22:44:26 denkblock kernel: [ 150.063223] shift: 32 Oct 14 22:44:26 denkblock kernel: [ 150.063225] mode: 3 Oct 14 22:44:26 denkblock kernel: [ 150.063227] next_event: 150070000000 nsecs Oct 14 22:44:26 denkblock kernel: [ 150.063230] set_next_event: lapic_next_event Oct 14 22:44:26 denkblock kernel: [ 150.063234] set_mode: lapic_timer_setup Oct 14 22:44:26 denkblock kernel: [ 150.063237] event_handler: tick_nohz_handler Oct 14 22:44:26 denkblock kernel: [ 150.063241] --8<---------------dmesg---------------end--------------->8--- ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-14 22:01 ` Elias Oltmanns @ 2008-10-15 8:43 ` Thomas Gleixner 2008-10-15 16:32 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-15 8:43 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Wed, 15 Oct 2008, Elias Oltmanns wrote: > Thomas Gleixner <tglx@linutronix.de> wrote: > > On Sat, 11 Oct 2008, Elias Oltmanns wrote: > >> > Compile the acpi_processor module in to the kernel > > > >> > (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel > >> > command line. If I analysed the problem correctly this will make the > >> > jiffies problem go away. I'm working on a fix. > >> > >> Spot on, it does go away regardless whether NO_HZ or HIGH_RES are > >> enabled or disabled. Looking forward to testing your fix ;-). > > > > Here you go. > > Bad luck, I'm afraid. Your patch seems to fix the issue for NO_HZ=n + > HIGH_RES=y. As soon as NO_HZ=y, however, the problem reappears. See the Hmm. You should have seen the same problem w/o that patch in the "CONFIG_ACPI_PROCESSOR=y / processor.max_cstate=1" test with NOHZ=y. Anyway, I can see what the NOHZ problem is. Updated patch below. > output below. (Still testing on 2.6.27, mind. Should I test something > more up-to-date?) .27 is fine. Did you make any progress finding out why the ath5k softirq runs for >20ms ? We need to fix this madness as well :) Thanks, tglx --- diff --git a/include/linux/tick.h b/include/linux/tick.h index 98921a3..b6ec818 100644 --- a/include/linux/tick.h +++ b/include/linux/tick.h @@ -96,9 +96,11 @@ extern cpumask_t *tick_get_broadcast_oneshot_mask(void); extern void tick_clock_notify(void); extern int tick_check_oneshot_change(int allow_nohz); extern struct tick_sched *tick_get_tick_sched(int cpu); +extern void tick_check_idle(int cpu); # else static inline void tick_clock_notify(void) { } static inline int tick_check_oneshot_change(int allow_nohz) { return 0; } +static inline void tick_check_idle(int cpu) { } # endif #else /* CONFIG_GENERIC_CLOCKEVENTS */ @@ -106,26 +108,23 @@ static inline void tick_init(void) { } static inline void tick_cancel_sched_timer(int cpu) { } static inline void tick_clock_notify(void) { } static inline int tick_check_oneshot_change(int allow_nohz) { return 0; } +static inline void tick_check_idle(int cpu) { } #endif /* !CONFIG_GENERIC_CLOCKEVENTS */ # ifdef CONFIG_NO_HZ extern void tick_nohz_stop_sched_tick(int inidle); extern void tick_nohz_restart_sched_tick(void); -extern void tick_nohz_update_jiffies(void); extern ktime_t tick_nohz_get_sleep_length(void); -extern void tick_nohz_stop_idle(int cpu); extern u64 get_cpu_idle_time_us(int cpu, u64 *last_update_time); # else static inline void tick_nohz_stop_sched_tick(int inidle) { } static inline void tick_nohz_restart_sched_tick(void) { } -static inline void tick_nohz_update_jiffies(void) { } static inline ktime_t tick_nohz_get_sleep_length(void) { ktime_t len = { .tv64 = NSEC_PER_SEC/HZ }; return len; } -static inline void tick_nohz_stop_idle(int cpu) { } static inline u64 get_cpu_idle_time_us(int cpu, u64 *unused) { return -1; } # endif /* !NO_HZ */ diff --git a/kernel/softirq.c b/kernel/softirq.c index c506f26..102cb1c 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -254,16 +254,12 @@ asmlinkage void do_softirq(void) */ void irq_enter(void) { -#ifdef CONFIG_NO_HZ int cpu = smp_processor_id(); + if (idle_cpu(cpu) && !in_interrupt()) - tick_nohz_stop_idle(cpu); -#endif + tick_check_idle(cpu); + __irq_enter(); -#ifdef CONFIG_NO_HZ - if (idle_cpu(cpu)) - tick_nohz_update_jiffies(); -#endif } #ifdef __ARCH_IRQ_EXIT_IRQS_DISABLED diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c index cb01cd8..f98a1b7 100644 --- a/kernel/time/tick-broadcast.c +++ b/kernel/time/tick-broadcast.c @@ -384,6 +384,19 @@ int tick_resume_broadcast_oneshot(struct clock_event_device *bc) } /* + * Called from irq_enter() when idle was interrupted to reenable the + * per cpu device. + */ +void tick_check_oneshot_broadcast(int cpu) +{ + if (cpu_isset(cpu, tick_broadcast_oneshot_mask)) { + struct tick_device *td = &per_cpu(tick_cpu_device, cpu); + + clockevents_set_mode(td->evtdev, CLOCK_EVT_MODE_ONESHOT); + } +} + +/* * Handle oneshot mode broadcasting */ static void tick_handle_oneshot_broadcast(struct clock_event_device *dev) diff --git a/kernel/time/tick-internal.h b/kernel/time/tick-internal.h index 4692487..b1c05bf 100644 --- a/kernel/time/tick-internal.h +++ b/kernel/time/tick-internal.h @@ -36,6 +36,7 @@ extern void tick_broadcast_switch_to_oneshot(void); extern void tick_shutdown_broadcast_oneshot(unsigned int *cpup); extern int tick_resume_broadcast_oneshot(struct clock_event_device *bc); extern int tick_broadcast_oneshot_active(void); +extern void tick_check_oneshot_broadcast(int cpu); # else /* BROADCAST */ static inline void tick_broadcast_setup_oneshot(struct clock_event_device *bc) { @@ -45,6 +46,7 @@ static inline void tick_broadcast_oneshot_control(unsigned long reason) { } static inline void tick_broadcast_switch_to_oneshot(void) { } static inline void tick_shutdown_broadcast_oneshot(unsigned int *cpup) { } static inline int tick_broadcast_oneshot_active(void) { return 0; } +static inline void tick_check_oneshot_broadcast(int cpu) { } # endif /* !BROADCAST */ #else /* !ONESHOT */ diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c index a4d2193..9877bdd 100644 --- a/kernel/time/tick-sched.c +++ b/kernel/time/tick-sched.c @@ -155,7 +155,7 @@ void tick_nohz_update_jiffies(void) touch_softlockup_watchdog(); } -void tick_nohz_stop_idle(int cpu) +static void tick_nohz_stop_idle(int cpu) { struct tick_sched *ts = &per_cpu(tick_cpu_sched, cpu); @@ -377,6 +377,32 @@ ktime_t tick_nohz_get_sleep_length(void) return ts->sleep_length; } +static void tick_nohz_restart(struct tick_sched *ts, ktime_t now) +{ + hrtimer_cancel(&ts->sched_timer); + ts->sched_timer.expires = ts->idle_tick; + + while (1) { + /* Forward the time to expire in the future */ + hrtimer_forward(&ts->sched_timer, now, tick_period); + + if (ts->nohz_mode == NOHZ_MODE_HIGHRES) { + hrtimer_start(&ts->sched_timer, + ts->sched_timer.expires, + HRTIMER_MODE_ABS); + /* Check, if the timer was already in the past */ + if (hrtimer_active(&ts->sched_timer)) + break; + } else { + if (!tick_program_event(ts->sched_timer.expires, 0)) + break; + } + /* Update jiffies and reread time */ + tick_do_update_jiffies64(now); + now = ktime_get(); + } +} + /** * tick_nohz_restart_sched_tick - restart the idle tick from the idle task * @@ -430,28 +456,7 @@ void tick_nohz_restart_sched_tick(void) */ ts->tick_stopped = 0; ts->idle_exittime = now; - hrtimer_cancel(&ts->sched_timer); - ts->sched_timer.expires = ts->idle_tick; - - while (1) { - /* Forward the time to expire in the future */ - hrtimer_forward(&ts->sched_timer, now, tick_period); - - if (ts->nohz_mode == NOHZ_MODE_HIGHRES) { - hrtimer_start(&ts->sched_timer, - ts->sched_timer.expires, - HRTIMER_MODE_ABS); - /* Check, if the timer was already in the past */ - if (hrtimer_active(&ts->sched_timer)) - break; - } else { - if (!tick_program_event(ts->sched_timer.expires, 0)) - break; - } - /* Update jiffies and reread time */ - tick_do_update_jiffies64(now); - now = ktime_get(); - } + tick_nohz_restart(ts, now); local_irq_enable(); } @@ -503,10 +508,6 @@ static void tick_nohz_handler(struct clock_event_device *dev) update_process_times(user_mode(regs)); profile_tick(CPU_PROFILING); - /* Do not restart, when we are in the idle loop */ - if (ts->tick_stopped) - return; - while (tick_nohz_reprogram(ts, now)) { now = ktime_get(); tick_do_update_jiffies64(now); @@ -552,6 +553,27 @@ static void tick_nohz_switch_to_nohz(void) smp_processor_id()); } +/* + * When NOHZ is enabled and the tick is stopped, we need to kick the + * tick timer from irq_enter() so that the jiffies update is kept + * alive during long running softirqs. That's ugly as hell, but + * correctness is key even if we need to fix the offending softirq in + * the first place. + * + * Note, this is different to tick_nohz_restart. We just kick the + * timer and do not touch the other magic bits which need to be done + * when idle is left. + */ +static void tick_nohz_kick_tick(int cpu) +{ + struct tick_sched *ts = &per_cpu(tick_cpu_sched, cpu); + + if (!ts->tick_stopped) + return; + + tick_nohz_restart(ts, ktime_get()); +} + #else static inline void tick_nohz_switch_to_nohz(void) { } @@ -559,6 +581,19 @@ static inline void tick_nohz_switch_to_nohz(void) { } #endif /* NO_HZ */ /* + * Called from irq_enter to notify about the possible interruption of idle() + */ +void tick_check_idle(int cpu) +{ + tick_check_oneshot_broadcast(cpu); +#ifdef CONFIG_NO_HZ + tick_nohz_stop_idle(cpu); + tick_nohz_update_jiffies(); + tick_nohz_kick_tick(cpu); +#endif +} + +/* * High resolution timer specific code */ #ifdef CONFIG_HIGH_RES_TIMERS @@ -611,10 +646,6 @@ static enum hrtimer_restart tick_sched_timer(struct hrtimer *timer) profile_tick(CPU_PROFILING); } - /* Do not restart, when we are in the idle loop */ - if (ts->tick_stopped) - return HRTIMER_NORESTART; - hrtimer_forward(timer, now, tick_period); return HRTIMER_RESTART; ^ permalink raw reply related [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-15 8:43 ` Thomas Gleixner @ 2008-10-15 16:32 ` Elias Oltmanns 2008-10-15 19:53 ` Thomas Gleixner 0 siblings, 1 reply; 27+ messages in thread From: Elias Oltmanns @ 2008-10-15 16:32 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Wed, 15 Oct 2008, Elias Oltmanns wrote: >> Thomas Gleixner <tglx@linutronix.de> wrote: > >> > On Sat, 11 Oct 2008, Elias Oltmanns wrote: >> >> > Compile the acpi_processor module in to the kernel >> > >> >> > (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel >> >> > command line. If I analysed the problem correctly this will make the >> >> > jiffies problem go away. I'm working on a fix. >> >> >> >> Spot on, it does go away regardless whether NO_HZ or HIGH_RES are >> >> enabled or disabled. Looking forward to testing your fix ;-). >> > >> > Here you go. >> >> Bad luck, I'm afraid. Your patch seems to fix the issue for NO_HZ=n + >> HIGH_RES=y. As soon as NO_HZ=y, however, the problem reappears. See the > > Hmm. You should have seen the same problem w/o that patch in the > "CONFIG_ACPI_PROCESSOR=y / processor.max_cstate=1" test with NOHZ=y. Right you are, I've just retested that case. The reason why I didn't hit this the last time is that it seems to be triggered far less often than without the processor.max_cstate=1 option. > > Anyway, I can see what the NOHZ problem is. Updated patch below. Nice, it seems to have done the trick. I'll keep an eye on my logs to make sure it doesn't pop up again. > >> output below. (Still testing on 2.6.27, mind. Should I test something >> more up-to-date?) > > .27 is fine. > > Did you make any progress finding out why the ath5k softirq runs for > >20ms ? We need to fix this madness as well :) Well, it wasn't obvious to me so far, whether the logs really indicated that 20 msecs had been spent in te callback or whether all this was due to the bug in the timing code. With your patch applied, I have eventually made further investigations into the matter. The problem is the following snippet from drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration(): /* * Enable noise floor calibration */ AR5K_REG_ENABLE_BITS(ah, AR5K_PHY_AGCCTL, AR5K_PHY_AGCCTL_NF); ret = ath5k_hw_register_timeout(ah, AR5K_PHY_AGCCTL, AR5K_PHY_AGCCTL_NF, 0, false); The first call sets a bit in the AR5K_PHY_AGCCTL register and the second waits for that bit to be cleared by the hardware again. Apparently, it takes roughly 20 ms to clear that bit. In order to execute ath5k_hw_noise_floor_calibration() in process context, I'd suggest introducing a single threaded workqueue for the ath5k driver and scheduling calibration from the calib_timer callback. Additionally, it would be necessary to schedule resets in a similar manner instead of using the ath5k_tasklet_reset() tasklet. This requires some serialisation but in my opinion there are various serialisation issues in ath5k as it is that need fixing. Unfortunately, none of the concerns I have raised wrt the ath5k driver seem to have resulted in a commit that I'm aware of even though patches have been supplied. Perhaps it's the merge window that consumes people's resources. Maybe I'll post a patch addressing this particular issue in the next few days. Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-15 16:32 ` Elias Oltmanns @ 2008-10-15 19:53 ` Thomas Gleixner 2008-10-17 21:03 ` Elias Oltmanns 0 siblings, 1 reply; 27+ messages in thread From: Thomas Gleixner @ 2008-10-15 19:53 UTC (permalink / raw) To: Elias Oltmanns; +Cc: Jiri Slaby, linux-wireless On Wed, 15 Oct 2008, Elias Oltmanns wrote: > Thomas Gleixner <tglx@linutronix.de> wrote: > > On Wed, 15 Oct 2008, Elias Oltmanns wrote: > >> Thomas Gleixner <tglx@linutronix.de> wrote: > > > >> > On Sat, 11 Oct 2008, Elias Oltmanns wrote: > >> >> > Compile the acpi_processor module in to the kernel > >> > > >> >> > (CONFIG_ACPI_PROCESSOR=y) and add processor.max_cstate=1 to the kernel > >> >> > command line. If I analysed the problem correctly this will make the > >> >> > jiffies problem go away. I'm working on a fix. > >> >> > >> >> Spot on, it does go away regardless whether NO_HZ or HIGH_RES are > >> >> enabled or disabled. Looking forward to testing your fix ;-). > >> > > >> > Here you go. > >> > >> Bad luck, I'm afraid. Your patch seems to fix the issue for NO_HZ=n + > >> HIGH_RES=y. As soon as NO_HZ=y, however, the problem reappears. See the > > > > Hmm. You should have seen the same problem w/o that patch in the > > "CONFIG_ACPI_PROCESSOR=y / processor.max_cstate=1" test with NOHZ=y. > > Right you are, I've just retested that case. The reason why I didn't hit > this the last time is that it seems to be triggered far less often than > without the processor.max_cstate=1 option. > > > > > Anyway, I can see what the NOHZ problem is. Updated patch below. > > Nice, it seems to have done the trick. I'll keep an eye on my logs to > make sure it doesn't pop up again. Thanks. I queue it for .28 and tag it for stable as well. > > > >> output below. (Still testing on 2.6.27, mind. Should I test something > >> more up-to-date?) > > > > .27 is fine. > > > > Did you make any progress finding out why the ath5k softirq runs for > > >20ms ? We need to fix this madness as well :) > > Well, it wasn't obvious to me so far, whether the logs really indicated > that 20 msecs had been spent in te callback or whether all this was due > to the bug in the timing code. With your patch applied, I have > eventually made further investigations into the matter. The problem is > the following snippet from > drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration(): > > /* > * Enable noise floor calibration > */ > AR5K_REG_ENABLE_BITS(ah, AR5K_PHY_AGCCTL, > AR5K_PHY_AGCCTL_NF); > > ret = ath5k_hw_register_timeout(ah, AR5K_PHY_AGCCTL, > AR5K_PHY_AGCCTL_NF, 0, false); > > The first call sets a bit in the AR5K_PHY_AGCCTL register and the second > waits for that bit to be cleared by the hardware again. Apparently, it > takes roughly 20 ms to clear that bit. That happens in softirq context ? So to verify this it's easy to just measure the time with ktime_get() across the both calls. > In order to execute ath5k_hw_noise_floor_calibration() in process > context, I'd suggest introducing a single threaded workqueue for the > ath5k driver and scheduling calibration from the calib_timer callback. > Additionally, it would be necessary to schedule resets in a similar > manner instead of using the ath5k_tasklet_reset() tasklet. This requires > some serialisation but in my opinion there are various serialisation > issues in ath5k as it is that need fixing. Unfortunately, none of the > concerns I have raised wrt the ath5k driver seem to have resulted in a > commit that I'm aware of even though patches have been supplied. Perhaps > it's the merge window that consumes people's resources. Maybe I'll post > a patch addressing this particular issue in the next few days. Sounds like a candidate for threaded interrupt handler :) Anyway, measuring the time of the softirq and pointing it out when it takes more than a couple of cycles is the right thing to do. Thanks, tglx ^ permalink raw reply [flat|nested] 27+ messages in thread
* Re: ath5k: kernel timing screwed - due to unserialised register access? 2008-10-15 19:53 ` Thomas Gleixner @ 2008-10-17 21:03 ` Elias Oltmanns 0 siblings, 0 replies; 27+ messages in thread From: Elias Oltmanns @ 2008-10-17 21:03 UTC (permalink / raw) To: Thomas Gleixner; +Cc: Jiri Slaby, linux-wireless Thomas Gleixner <tglx@linutronix.de> wrote: > On Wed, 15 Oct 2008, Elias Oltmanns wrote: >> Thomas Gleixner <tglx@linutronix.de> wrote: [...] >> > Anyway, I can see what the NOHZ problem is. Updated patch below. >> >> Nice, it seems to have done the trick. I'll keep an eye on my logs to >> make sure it doesn't pop up again. > > Thanks. I queue it for .28 and tag it for stable as well. Thanks for taking your time to get this sorted. [...] >> > Did you make any progress finding out why the ath5k softirq runs for >> > >20ms ? We need to fix this madness as well :) >> >> Well, it wasn't obvious to me so far, whether the logs really indicated >> that 20 msecs had been spent in te callback or whether all this was due >> to the bug in the timing code. With your patch applied, I have >> eventually made further investigations into the matter. The problem is >> the following snippet from >> drivers/net/wireless/ath5k/phy.c:ath5k_hw_noise_floor_calibration(): >> >> /* >> * Enable noise floor calibration >> */ >> AR5K_REG_ENABLE_BITS(ah, AR5K_PHY_AGCCTL, >> AR5K_PHY_AGCCTL_NF); >> >> ret = ath5k_hw_register_timeout(ah, AR5K_PHY_AGCCTL, >> AR5K_PHY_AGCCTL_NF, 0, false); >> >> The first call sets a bit in the AR5K_PHY_AGCCTL register and the second >> waits for that bit to be cleared by the hardware again. Apparently, it >> takes roughly 20 ms to clear that bit. > > That happens in softirq context ? So to verify this it's easy to just > measure the time with ktime_get() across the both calls. Yes, that's how I narrowed it down to those two calls in the first place. Well, in fact it's just the for loop polling the register in ath5k_hw_register_timeout() to see whether the bit has been cleared yet. It looks like this: for (i = AR5K_TUNE_REGISTER_TIMEOUT; i > 0; i--) { data = ath5k_hw_reg_read(ah, reg); if (is_set && (data & flag)) break; else if ((data & flag) == val) break; udelay(15); } AR5K_TUNE_REGISTER_TIMEOUT is defined as 20000. On my system, i usually is something round about 18700 on exit from the for loop. This accounts for roughly 20 msecs. > >> In order to execute ath5k_hw_noise_floor_calibration() in process >> context, I'd suggest introducing a single threaded workqueue for the >> ath5k driver and scheduling calibration from the calib_timer callback. >> Additionally, it would be necessary to schedule resets in a similar >> manner instead of using the ath5k_tasklet_reset() tasklet. This requires >> some serialisation but in my opinion there are various serialisation >> issues in ath5k as it is that need fixing. Unfortunately, none of the >> concerns I have raised wrt the ath5k driver seem to have resulted in a >> commit that I'm aware of even though patches have been supplied. Perhaps >> it's the merge window that consumes people's resources. Maybe I'll post >> a patch addressing this particular issue in the next few days. > > Sounds like a candidate for threaded interrupt handler :) > > Anyway, measuring the time of the softirq and pointing it out when it > takes more than a couple of cycles is the right thing to do. Executing the whole calibration takes between 20 and 23 msecs on my system. Regards, Elias ^ permalink raw reply [flat|nested] 27+ messages in thread
end of thread, other threads:[~2008-10-17 21:03 UTC | newest] Thread overview: 27+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2008-10-05 21:45 ath5k: kernel timing screwed - due to unserialised register access? Elias Oltmanns 2008-10-05 21:59 ` Thomas Gleixner 2008-10-06 14:04 ` Elias Oltmanns 2008-10-06 19:47 ` Thomas Gleixner 2008-10-07 15:27 ` Elias Oltmanns 2008-10-07 18:02 ` Thomas Gleixner 2008-10-07 18:44 ` Thomas Gleixner 2008-10-07 21:23 ` Elias Oltmanns 2008-10-08 11:39 ` Elias Oltmanns 2008-10-08 21:14 ` Thomas Gleixner 2008-10-09 11:15 ` Thomas Gleixner 2008-10-10 8:33 ` Elias Oltmanns 2008-10-10 10:13 ` Thomas Gleixner 2008-10-10 11:50 ` Elias Oltmanns 2008-10-10 12:34 ` Thomas Gleixner 2008-10-10 12:59 ` Elias Oltmanns 2008-10-10 21:32 ` Christoph Hellwig 2008-10-11 9:55 ` Thomas Gleixner 2008-10-10 19:24 ` Nick Kossifidis 2008-10-11 9:54 ` Thomas Gleixner 2008-10-11 20:30 ` Elias Oltmanns 2008-10-14 19:00 ` Thomas Gleixner 2008-10-14 22:01 ` Elias Oltmanns 2008-10-15 8:43 ` Thomas Gleixner 2008-10-15 16:32 ` Elias Oltmanns 2008-10-15 19:53 ` Thomas Gleixner 2008-10-17 21:03 ` Elias Oltmanns
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).