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