ath5k: kernel timing screwed - due to unserialised register access?
Subsystems (3)
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
Quoted 12 lines · Elias Oltmanns
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);
Quoted 8 lines
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
Quoted 23 lines · Thomas Gleixner
Quoted 13 lines · Elias Oltmanns
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);Quoted 8 lines
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.
Quoted 4 lines
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=nandCONFIG_HIGH_RES_TIMERS=nor 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).
Quoted 4 lines
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
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
drivers/misc/Kconfig +11 -0
@@ -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
drivers/misc/Makefile +1 -0
@@ -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
drivers/misc/timer-test.c new file +80 -0
80 lines not on this page · raw message
#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;
}Quoted 2 lines · Elias Oltmanns
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
Quoted 3 lines · Thomas Gleixner
Quoted 2 lines · Elias Oltmanns
Make sure that event1 is the right device. chktimer usually reports several premature timer expiries in less than a minute.
[...]
Quoted 3 lines
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
drivers/misc/Kconfig +11 -0
@@ -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
drivers/misc/Makefile +1 -0
@@ -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
drivers/misc/timer-test.c new file +50 -0
50 lines not on this page · raw message
Quoted 4 lines · Elias Oltmanns
Quoted 3 lines · Thomas Gleixner
Quoted 2 lines · Elias Oltmanns
Make sure that event1 is the right device. chktimer usually reports several premature timer expiries in less than a minute.
Quoted 8 lines
[...]
Quoted 3 lines
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
Quoted 2 lines
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 :)
drivers/misc/timer-test.c line 24
Quoted 2 lines
drivers/misc/timer-test.c new file +2
-0+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
Quoted 26 lines · Thomas Gleixner
Quoted 4 lines · Elias Oltmanns
Quoted 3 lines · Thomas Gleixner
Quoted 2 lines · Elias Oltmanns
Make sure that event1 is the right device. chktimer usually reports several premature timer expiries in less than a minute.
Quoted 8 lines
[...]
Quoted 3 lines
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
-ENOATH5KHARDWAREQuoted 2 lines
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 :)
drivers/misc/timer-test.c line 24
Quoted 2 lines
drivers/misc/timer-test.c new file +2
-0+if (timespec_to_ns (&diff) <TSTM_THRESH ) +printk (KERN_INFO "Timer expired prematurely.\n" );e.g.:
Quoted 5 lines
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
Quoted 12 lines · Thomas Gleixner
Quoted 11 lines · Thomas Gleixner
Quoted 9 lines · Elias Oltmanns
Quoted 3 lines · Thomas Gleixner
Quoted 2 lines · Elias Oltmanns
Make sure that event1 is the right device. chktimer usually reports several premature timer expiries in less than a minute.
[...]
Quoted 3 lines
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.
Quoted 5 lines
Quoted 5 lines
Quoted 3 lines
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.
Quoted 11 lines
Quoted 11 lines
Quoted 3 lines
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 :)
drivers/misc/timer-test.c line 24
Quoted 2 lines
drivers/misc/timer-test.c new file +2
-0+if (timespec_to_ns (&diff) <TSTM_THRESH ) +printk (KERN_INFO "Timer expired prematurely.\n" );e.g.:
Quoted 5 lines
Quoted 5 lines
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.
Quoted 7 lines
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_HZenabled 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, ...
Quoted 9 lines
Can you please add:
sysrq_timer_list_show();after the printk. You have to export it in
kernel/time/timer_list.cto use it with a modulePlease do cat
/proc/timer_listright 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.3HRTIMER_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_broadcasttick_broadcast_mask: 00000001tick_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
Quoted 1 line · Elias Oltmanns
Thomas Gleixner <[email protected]> wrote:
[...]
Quoted 10 lines
Quoted 4 lines
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_HZenabled is the most important option to trigger the problem speedily.HIGHRES_TIMERSdidn't seem to make much difference and I am quite sure that I observed this issue withNO_HZdisabled 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 setCONFIG_HIGH_RES_TIMERS=y
--8<---------------/proc/timer_list---------------start------------->8--- Timer List Version: v0.3HRTIMER_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_broadcasttick_broadcast_mask: 00000001tick_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=yCONFIG_HIGH_RES_TIMERS=y
--8<---------------/proc/timer_list---------------start------------->8--- Timer List Version: v0.3HRTIMER_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_broadcasttick_broadcast_mask: 00000001tick_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---
Quoted 14 lines · Elias Oltmanns
Quoted 1 line · Elias Oltmanns
Thomas Gleixner <[email protected]> wrote:
[...]
Quoted 10 lines
Quoted 4 lines
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_HZenabled is the most important option to trigger the problem speedily.HIGHRES_TIMERSdidn't seem to make much difference and I am quite sure that I observed this issue withNO_HZdisabled too, but very rarely. I'll keep testing and reporting. Meanwhile, ...
Quoted 8 lines
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_HZandHIGH_RES_TIMERSdisabled, but in vain. All other combinations trigger the described problem, so I have appended the requested data. There is one more odd thing: withNO_HZdisabled andHIGH_RES_TIMERSenabled, 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
Quoted 4 lines · Thomas Gleixner
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
include/linux/tick.h +3 -0
@@ -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 );
kernel/time/tick-sched.c +8 -0
@@ -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
kernel/time/timer_list.c +3 -0
@@ -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); }
Quoted 8 lines · Thomas Gleixner
Quoted 4 lines · Thomas Gleixner
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 setCONFIG_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---
Quoted 59 lines
Thanks,
tglx
include/linux/tick.h +3
-0@@ -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 );kernel/time/tick-sched.c +8
-0@@ -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 kernel/time/timer_list.c +3
-0@@ -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); }
Quoted 10 lines · Elias Oltmanns
Quoted 8 lines · Thomas Gleixner
Quoted 4 lines · Thomas Gleixner
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?
Quoted 7 lines
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:
Quoted 6 lines
[ 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:
Quoted 3 lines
[ 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
---
kernel/softirq.c +5 -0
@@ -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++;
Quoted 57 lines · Thomas Gleixner
Quoted 11 lines · Elias Oltmanns
Quoted 8 lines · Thomas Gleixner
Quoted 4 lines · Thomas Gleixner
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?
Quoted 7 lines
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:
Quoted 6 lines
[ 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_timeris the one which updates jiffies. next expiry: 136.840So at HZ=250 we expect that it expired at:
136.836, 136.832, 136.828, 136.824, 136.820, 136.816, 136.812so we would have expected to see
.last_events0 136.828 .last_events1 136.832 .last_events2 136.836but we get:
Quoted 3 lines
[ 136.838434] .last_events0 : 136812009783 nsecs [ 136.838437] .last_events1 : 136816009783 nsecs [ 136.838440] .last_events2 : 136838253113 nsecsThe 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
Quoted 7 lines
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
Quoted 6 lines · Elias Oltmanns
That
printk()has not been hit, I'm afraid. The output ofsysrq_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.
Quoted 6 lines
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.
Quoted 10 lines
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;
}
}Quoted 4 lines
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
Quoted 11 lines · Thomas Gleixner
Quoted 10 lines · Elias Oltmanns
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:
Quoted 6 lines
Quoted 3 lines
/* 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
2008/10/10 Thomas Gleixner <[email protected]>:
Quoted 32 lines · Elias Oltmanns
Quoted 6 lines
That
printk()has not been hit, I'm afraid. The output ofsysrq_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.Quoted 6 lines
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.
Quoted 10 lines
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; } }Quoted 4 lines
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
Quoted 6 lines
That makes sense. The timer expires early events are multiples of 10s apart.
Thanks,
tglx
What should we use then ? udelay(1000) ?
Signature · 3 lines
GPG ID: 0xD21DB2DB As you read this post global entropy rises. Have Fun ;-) Nick
Quoted 3 lines · Elias Oltmanns
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.
Quoted 27 lines · Thomas Gleixner
Quoted 6 lines · Elias Oltmanns
That
printk()has not been hit, I'm afraid. The output ofsysrq_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.Quoted 6 lines
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.
Quoted 10 lines
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; } }
Quoted 7 lines
Quoted 4 lines
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 ourThat 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
Quoted 6 lines · Christoph Hellwig
Quoted 3 lines · Elias Oltmanns
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.
Quoted 2 lines · Thomas Gleixner
Quoted 1 line · Thomas Gleixner
On Fri, 10 Oct 2008, Elias Oltmanns wrote:
[...]
Quoted 11 lines
Quoted 7 lines
Quoted 4 lines
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 ourThat 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.
Quoted 6 lines
Can you please try the following:
Compile the
acpi_processormodule 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
Quoted 7 lines · Elias Oltmanns
Quoted 4 lines
Compile the
acpi_processormodule 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_HZorHIGH_RESare enabled or disabled. Looking forward to testing your fix ;-).
Here you go.
tglx
---
include/linux/tick.h +2 -4
@@ -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 */
kernel/softirq.c +4 -8
@@ -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
kernel/time/tick-broadcast.c +13 -0
@@ -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)
kernel/time/tick-internal.h +2 -0
@@ -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 */
kernel/time/tick-sched.c +15 -1
@@ -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
Quoted 11 lines · Thomas Gleixner
Quoted 8 lines · Elias Oltmanns
Quoted 5 lines
Compile the
acpi_processormodule 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_HZorHIGH_RESare 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---
Quoted 8 lines · Elias Oltmanns
Quoted 7 lines · Thomas Gleixner
Quoted 6 lines · Elias Oltmanns
Quoted 5 lines
Compile the
acpi_processormodule 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.
Quoted 7 lines
Quoted 4 lines
Quoted 2 lines
Spot on, it does go away regardless whether
NO_HZorHIGH_RESare 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.
Quoted 2 lines
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
Quoted 1 line
20ms ? We need to fix this madness as well :)
Thanks,
tglx
---
include/linux/tick.h +3 -4
@@ -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 */
kernel/softirq.c +3 -7
@@ -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
kernel/time/tick-broadcast.c +13 -0
@@ -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)
kernel/time/tick-internal.h +2 -0
@@ -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 */
kernel/time/tick-sched.c +62 -31
135 lines not on this page · raw message
Quoted 13 lines · Thomas Gleixner
Quoted 12 lines · Elias Oltmanns
Quoted 10 lines · Thomas Gleixner
Quoted 8 lines · Elias Oltmanns
Quoted 5 lines
Compile the
acpi_processormodule 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_HZorHIGH_RESare enabled or disabled. Looking forward to testing your fix ;-).
Quoted 7 lines
Quoted 4 lines
Quoted 1 line
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.
Quoted 2 lines
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.
Quoted 8 lines
Quoted 3 lines
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
Quoted 1 line
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
Quoted 27 lines · Elias Oltmanns
Quoted 13 lines · Thomas Gleixner
Quoted 12 lines · Elias Oltmanns
Quoted 10 lines · Thomas Gleixner
Quoted 8 lines · Elias Oltmanns
Quoted 5 lines
Compile the
acpi_processormodule 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_HZorHIGH_RESare enabled or disabled. Looking forward to testing your fix ;-).Quoted 7 lines
Quoted 4 lines
Quoted 1 line
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.
Quoted 1 line
Quoted 4 lines
Quoted 1 line
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.
Quoted 25 lines
Quoted 8 lines
Quoted 3 lines
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
Quoted 1 line
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);
Quoted 3 lines
The first call sets a bit in the
AR5K_PHY_AGCCTLregister 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.
Quoted 11 lines
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 thecalib_timercallback. Additionally, it would be necessary to schedule resets in a similar manner instead of using theath5k_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
Quoted 2 lines · Thomas Gleixner
Quoted 1 line · Elias Oltmanns
Thomas Gleixner <[email protected]> wrote:
[...]
Quoted 6 lines
Quoted 4 lines
Quoted 1 line
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.
[...]
Quoted 19 lines
Quoted 19 lines
Quoted 2 lines
Did you make any progress finding out why the ath5k softirq runs for
Quoted 1 line
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);
Quoted 6 lines
Quoted 3 lines
The first call sets a bit in the
AR5K_PHY_AGCCTLregister 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.
Quoted 13 lines
Quoted 12 lines
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 thecalib_timercallback. Additionally, it would be necessary to schedule resets in a similar manner instead of using theath5k_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.
Quoted 4 lines
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