I have been suffering from lost ticks for several months now ever since I
switched to an X86_64 kernel with SMP. I have read previous posts about lost
ticks due to TSC timer, but I have been having a different problem as I have
only been using 2.6.14 and then 2.6.15 kernels and only PM timers. Also, this
problem does not manifest itself immedietly, I could be using the system for
anywhere from a few hours to a couple of days without any problems before I
start losing ticks, but once it starts it would lose them constantly and my
desktop becomes unstable (some apps crash, while other take 5 minutes to
start up, this was what led me to discover the lost ticks) forcing me to
reboot. The following error appears in dmesg at the time the system starts to
act strange
Losing some ticks... checking if CPU frequency changed.
warning: many lost ticks.
Your time source seems to be instable or some driver is hogging interupts
rip __do_softirq+0x47/0xd1
adding report_lost_ticks only prints repeating messages like
Lost 3 timer tick(s)! rip __do_softirq+0x47/0xd1
I have tried using acipmaintimer and acippmtimer, it would boot fine but I
would notice the following in dmesg
..MP-BIOS bug: 8254 timer not connected to IO-APIC
timer doesn't work through the IO-APIC - disabling NMI Watchdog!
Uhhuh. NMI received for unknown reason 3d.
And would still end up with lost ticks eventually. using acpi=off causes the
entire system to come to a crawl (I am guessing this is due to the PM timer).
For the life of me I can't seem to figure out what causes these lost ticks to
start, but when they do the /proc/interrupts show a drop from roughly 1000
interrupts/sec to around 700 and this persists until I reboot.
My hardware is an AMD64 X2 4800+ on an asus A8N-SLI.
Also, could I please be CC'ed to any replies. I don't mean to be rude by not
subscribing but I couldn't handle the volume.
Thanks,
Abdulla Bubshait
On Tue, Feb 28, 2006 at 12:22:40AM +0300, bubshait wrote:
> Losing some ticks... checking if CPU frequency changed.
> warning: many lost ticks.
> Your time source seems to be instable or some driver is hogging interupts
> rip __do_softirq+0x47/0xd1
>
> adding report_lost_ticks only prints repeating messages like
>
> Lost 3 timer tick(s)! rip __do_softirq+0x47/0xd1
I'm seeing tons of these on a Tyan 2895 (Nvidia CKO4) running FC4 with
kernel-2.6.15-1.1830 (2.6.15.2) SMP:
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
[I've seen the same thing with earlier FC 2.6.14 kernels.]
On our systems the __do_softirq messages are strongly correlated with
sata_nv interrupts, especially during our nightly tripwire-like fs
checksum job. Unfortunately, the log messages are not very informative.
I'm not sure what ever happened to the following patch,
http://www.kernel.org/pub/linux/kernel/people/akpm/patches/2.5/2.5.64/2.5.64-mm3/broken-out/report-lost-ticks.patch
but it was dropped.
Unfortunately, I need to spend tomorrow patching kernels in search of a
fix or workaround, as I have to start using these boxes in production,
and they need to keep time.
Regards,
Bill Rugolsky
On Mon, 27 Feb 2006, Bill Rugolsky Jr. wrote:
> On Tue, Feb 28, 2006 at 12:22:40AM +0300, bubshait wrote:
> > Losing some ticks... checking if CPU frequency changed.
> > warning: many lost ticks.
> > Your time source seems to be instable or some driver is hogging interupts
> > rip __do_softirq+0x47/0xd1
> >
> > adding report_lost_ticks only prints repeating messages like
> >
> > Lost 3 timer tick(s)! rip __do_softirq+0x47/0xd1
>
> I'm seeing tons of these on a Tyan 2895 (Nvidia CKO4) running FC4 with
> kernel-2.6.15-1.1830 (2.6.15.2) SMP:
>
> time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
> time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
>
> [I've seen the same thing with earlier FC 2.6.14 kernels.]
>
> On our systems the __do_softirq messages are strongly correlated with
> sata_nv interrupts, especially during our nightly tripwire-like fs
> checksum job. Unfortunately, the log messages are not very informative.
> I'm not sure what ever happened to the following patch,
>
> http://www.kernel.org/pub/linux/kernel/people/akpm/patches/2.5/2.5.64/2.5.64-mm3/broken-out/report-lost-ticks.patch
>
> but it was dropped.
>
> Unfortunately, I need to spend tomorrow patching kernels in search of a
> fix or workaround, as I have to start using these boxes in production,
> and they need to keep time.
>
passing 'nohpet' and/or 'nopmtimer' will force the use of a different
timer...but this is certainly a workaround, if it helps...
On Tuesday 28 February 2006 01:47, Jason Baron wrote:
> On Mon, 27 Feb 2006, Bill Rugolsky Jr. wrote:
> > On Tue, Feb 28, 2006 at 12:22:40AM +0300, bubshait wrote:
> > > Losing some ticks... checking if CPU frequency changed.
> > > warning: many lost ticks.
> > > Your time source seems to be instable or some driver is hogging
> > > interupts rip __do_softirq+0x47/0xd1
> > >
> > > adding report_lost_ticks only prints repeating messages like
> > >
> > > Lost 3 timer tick(s)! rip __do_softirq+0x47/0xd1
> >
> > I'm seeing tons of these on a Tyan 2895 (Nvidia CKO4) running FC4 with
> > kernel-2.6.15-1.1830 (2.6.15.2) SMP:
> >
> > time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
> > time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
> >
> > [I've seen the same thing with earlier FC 2.6.14 kernels.]
> >
> > On our systems the __do_softirq messages are strongly correlated with
> > sata_nv interrupts, especially during our nightly tripwire-like fs
> > checksum job. Unfortunately, the log messages are not very informative.
> > I'm not sure what ever happened to the following patch,
> >
> > http://www.kernel.org/pub/linux/kernel/people/akpm/patches/2.5/2.5.64/2.5
> >.64-mm3/broken-out/report-lost-ticks.patch
> >
> > but it was dropped.
> >
> > Unfortunately, I need to spend tomorrow patching kernels in search of a
> > fix or workaround, as I have to start using these boxes in production,
> > and they need to keep time.
>
> passing 'nohpet' and/or 'nopmtimer' will force the use of a different
> timer...but this is certainly a workaround, if it helps...
Unfortunately, I can't seem to find a way to force it to use hpet. Passing
'notsc' and 'nopmtimer' I end up using PIT/TSC based timekeeping. TSC is
already known to have problems with dual core. But I will sit with it for a
while to see if it fairs better than the pm timer.
Bill, What timer do you use, and do these lost ticks persist after sata_nv
interrupts stop?
On Tuesday 28 February 2006 01:47, you wrote:
> On Mon, 27 Feb 2006, Bill Rugolsky Jr. wrote:
> > On Tue, Feb 28, 2006 at 12:22:40AM +0300, bubshait wrote:
> > > Losing some ticks... checking if CPU frequency changed.
> > > warning: many lost ticks.
> > > Your time source seems to be instable or some driver is hogging
> > > interupts rip __do_softirq+0x47/0xd1
> > >
> > > adding report_lost_ticks only prints repeating messages like
> > >
> > > Lost 3 timer tick(s)! rip __do_softirq+0x47/0xd1
> >
> > I'm seeing tons of these on a Tyan 2895 (Nvidia CKO4) running FC4 with
> > kernel-2.6.15-1.1830 (2.6.15.2) SMP:
> >
> > time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
> > time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
> >
> > [I've seen the same thing with earlier FC 2.6.14 kernels.]
> >
> > On our systems the __do_softirq messages are strongly correlated with
> > sata_nv interrupts, especially during our nightly tripwire-like fs
> > checksum job. Unfortunately, the log messages are not very informative.
> > I'm not sure what ever happened to the following patch,
> >
> > http://www.kernel.org/pub/linux/kernel/people/akpm/patches/2.5/2.5.64/2.5
> >.64-mm3/broken-out/report-lost-ticks.patch
> >
> > but it was dropped.
> >
> > Unfortunately, I need to spend tomorrow patching kernels in search of a
> > fix or workaround, as I have to start using these boxes in production,
> > and they need to keep time.
>
> passing 'nohpet' and/or 'nopmtimer' will force the use of a different
> timer...but this is certainly a workaround, if it helps...
TSC timer is useless and the kernel can't seem to find the hpet, unfortunately
nosmp doesn't even boot so that workaround is blocked too.
Trying to go through this problem some more, I would have to agree that it
could be the sata_nv interrupts that are throwing off the time, but what I
don't seem to understand is how the pmtimer would persist at this new
interrupt rate of 700/s even after sata_nv interrupts drop off.
On Tue, Feb 28, 2006 at 10:41:27AM +0300, Abdulla Bubshait wrote:
> Unfortunately, I can't seem to find a way to force it to use hpet. Passing
> 'notsc' and 'nopmtimer' I end up using PIT/TSC based timekeeping. TSC is
> already known to have problems with dual core. But I will sit with it for a
> while to see if it fairs better than the pm timer.
>
> Bill, What timer do you use, and do these lost ticks persist after sata_nv
> interrupts stop?
Sorry for the late reply. I'm using pmtimer (the default). I
get lost ticks reported mostly in default_idle and __do_softirq.
The machine is running PostgreSQL, so the Lost tick messages occur
throughout the day, but they come frequently during our nightly cron
jobs that do rsyncs, checksums, etc. So far today:
rugolsky@ti88: awk '/Feb 28.*Lost.*timer/{n++;sum+=$8};END{printf "%d messages, %d lost ticks\n",n,sum}' /var/log/messages
487 messages, 588 lost ticks
And this month:
rugolsky@ti88: awk '/Feb .*Lost.*timer/{n++;sum+=$8};END{printf "%d messages, %d lost ticks\n",n,sum}' /var/log/messages*
19051 messages, 23794 lost ticks
I got another test machine up and running today, so I can start patching and
testing tomorrow.
Bill Rugolsky
"Bill Rugolsky Jr." <[email protected]> writes:
>
> The machine is running PostgreSQL, so the Lost tick messages occur
> throughout the day, but they come frequently during our nightly cron
> jobs that do rsyncs, checksums, etc. So far today:
What chipset?
> I got another test machine up and running today, so I can start patching and
> testing tomorrow.
What output do you get when you run ftp.suse.com:/pub/people/ak/tools/trtc.c ?
(and what is the _HZ value you configured in Kconfig?)
Does it go away when you run with idle=poll?
-Andi
On Wed, Mar 01, 2006 at 12:53:58AM +0100, Andi Kleen wrote:
> What chipset?
Thanks for the interest, Andi.
The chipset is NVIDIA nForce Pro 2200 (CK804). The mobo is Tyan 2895:
http://www.tyan.com/products/html/thunderk8we.html
It's running the current 1.02 version of the BIOS.
Current kernel is the FC4 errata:
Linux ti94 2.6.15-1.1831_FC4smp #1 SMP Tue Feb 7 13:51:52 EST 2006 x86_64 x86_64 x86_64 GNU/Linux
rugolsky@ti94: rpm -q --changelog kernel-smp-2.6.15-1.1831_FC4 | head -3
* Tue Feb 07 2006 Dave Jones <[email protected]>
- 2.6.15.3
Fixes remotely exploitable bug in ICMP (CVE-2006-0454)
Powernow-k8 is built into the kernel (see log messages below),
but I have it turned off in the BIOS config.
Some time today I'll build vanilla 2.6.15.4 and 2.6.16-rc5.
> What output do you get when you run ftp.suse.com:/pub/people/ak/tools/trtc.c ?
> (and what is the _HZ value you configured in Kconfig?)
rugolsky@ti94: grep CONFIG_HZ /usr/src/kernels/2.6.15-1.1831_FC4smp-x86_64/.config
# CONFIG_HZ_100 is not set
CONFIG_HZ_250=y
# CONFIG_HZ_1000 is not set
CONFIG_HZ=250
Below is the trtc output while running "find /usr -type f | cpio -o > /dev/null"
without and with idle=poll.
> Does it go away when you run with idle=poll?
No.
Here's some output of trtc without idle=poll:
1141220165:151240: rtc 464 int 0 125 (=125)
1141220165:651241: rtc 448 int 0 125 (=125)
1141220166:151242: rtc 464 int 0 125 (=125)
1141220166:651244: rtc 448 int 0 125 (=125)
1141220167:151245: rtc 464 int 0 125 (=125)
1141220167:651245: rtc 448 int 0 125 (=125)
1141220168:155246: rtc 464 int 0 125 (=125)
1141220168:655250: rtc 448 int 22 103 (=125)
1141220169:155280: rtc 464 int 125 0 (=125)
1141220169:655251: rtc 448 int 125 0 (=125)
1141220170:155251: rtc 464 int 125 0 (=125)
1141220170:655252: rtc 448 int 125 0 (=125)
1141220171:155253: rtc 464 int 125 0 (=125)
1141220171:655253: rtc 448 int 125 0 (=125)
1141220172:155288: rtc 464 int 125 0 (=125)
1141220172:655256: rtc 448 int 125 0 (=125)
1141220173:155258: rtc 464 int 125 0 (=125)
1141220173:655258: rtc 448 int 125 0 (=125)
1141220174:155259: rtc 464 int 125 0 (=125)
1141220174:655260: rtc 448 int 125 0 (=125)
1141220175:155262: rtc 464 int 125 0 (=125)
1141220175:655262: rtc 448 int 125 0 (=125)
1141220176:155263: rtc 464 int 125 0 (=125)
1141220176:655265: rtc 448 int 125 0 (=125)
1141220177:159266: rtc 464 int 125 0 (=125)
1141220177:659268: rtc 448 int 125 0 (=125)
1141220178:159268: rtc 464 int 125 0 (=125)
1141220178:659274: rtc 448 int 104 21 (=125)
1141220179:159272: rtc 464 int 0 125 (=125)
1141220179:659270: rtc 448 int 0 125 (=125)
1141220180:159272: rtc 464 int 0 125 (=125)
1141220180:659273: rtc 448 int 0 125 (=125)
1141220181:159274: rtc 464 int 0 125 (=125)
1141220181:659275: rtc 448 int 0 125 (=125)
1141220182:159276: rtc 464 int 0 125 (=125)
1141220182:659277: rtc 448 int 0 125 (=125)
1141220183:159283: rtc 464 int 0 125 (=125)
1141220183:659279: rtc 448 int 0 125 (=125)
1141220184:163288: rtc 464 int 0 123 (=123) <-----
1141220184:663281: rtc 448 int 0 125 (=125)
1141220185:163283: rtc 464 int 0 125 (=125)
1141220185:667283: rtc 448 int 0 125 (=125)
1141220186:167285: rtc 464 int 0 125 (=125)
1141220186:667285: rtc 448 int 0 125 (=125)
1141220187:167289: rtc 464 int 0 125 (=125)
1141220187:667288: rtc 448 int 0 125 (=125)
1141220188:167289: rtc 464 int 0 125 (=125)
1141220188:667292: rtc 448 int 22 103 (=125)
1141220189:167291: rtc 464 int 125 0 (=125)
1141220189:667291: rtc 448 int 125 0 (=125)
1141220190:167292: rtc 464 int 125 0 (=125)
1141220190:667293: rtc 448 int 125 0 (=125)
1141220191:167292: rtc 464 int 125 0 (=125)
Kernel log highlights:
Kernel command line: ro root=/dev/md2 report_lost_ticks
...
time.c: Using 3.579545 MHz PM timer.
time.c: Detected 2009.284 MHz processor.
...
Using local APIC timer interrupts.
Detected 12.558 MHz APIC timer.
time.c: Lost 11 timer tick(s)! rip setup_boot_APIC_clock+0x117/0x11a)
Booting processor 1/2 APIC 0x1
Initializing CPU#1
Calibrating delay using timer specific routine.. 4018.82 BogoMIPS (lpj=8037654)
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 1024K (64 bytes/line)
CPU 1(1) -> Node 0 -> Core 0
AMD Opteron(tm) Processor 246 stepping 0a
CPU 1: Syncing TSC to CPU 0.
CPU 1: synchronized TSC with CPU 0 (last diff -124 cycles, maxerr 1093 cycles)
Brought up 2 CPUs
Disabling vsyscall due to use of PM timer
time.c: Using PM based timekeeping.
testing NMI watchdog ... <4>time.c: Lost 17 timer tick(s)! rip __delay+0xa/0x10)
OK.
powernow-k8: Found 2 AMD Athlon 64 / Opteron processors (version 1.50.4)
powernow-k8: MP systems not supported by PSB BIOS structure
powernow-k8: MP systems not supported by PSB BIOS structure
...
time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 2 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 2 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
Here's the output of trtc with idle=poll:
1141221151:371869: rtc 464 int 125 0 (=125)
1141221151:871857: rtc 448 int 125 0 (=125)
1141221152:371845: rtc 464 int 125 0 (=125)
1141221152:871833: rtc 448 int 125 0 (=125)
1141221153:371820: rtc 464 int 125 0 (=125)
1141221153:871808: rtc 448 int 125 0 (=125)
1141221154:371796: rtc 464 int 125 0 (=125)
1141221154:871784: rtc 448 int 125 0 (=125)
1141221155:371771: rtc 464 int 71 54 (=125)
1141221155:871759: rtc 448 int 0 125 (=125)
1141221156:371745: rtc 464 int 0 125 (=125)
1141221156:871734: rtc 448 int 0 125 (=125)
1141221157:371721: rtc 464 int 0 125 (=125)
1141221157:871709: rtc 448 int 0 125 (=125)
1141221158:371696: rtc 464 int 0 125 (=125)
1141221158:871685: rtc 448 int 0 125 (=125)
1141221159:371672: rtc 464 int 0 125 (=125)
1141221159:871660: rtc 448 int 0 125 (=125)
1141221160:371648: rtc 464 int 0 125 (=125)
1141221160:871635: rtc 448 int 0 125 (=125)
1141221161:371622: rtc 464 int 0 125 (=125)
1141221161:871610: rtc 448 int 0 125 (=125)
1141221162:371599: rtc 464 int 0 125 (=125)
1141221162:871586: rtc 448 int 0 125 (=125)
1141221163:371573: rtc 464 int 0 125 (=125)
1141221163:871561: rtc 448 int 0 125 (=125)
1141221164:371549: rtc 464 int 0 125 (=125)
1141221164:871537: rtc 448 int 0 125 (=125)
1141221165:371526: rtc 464 int 53 72 (=125)
1141221165:871510: rtc 448 int 125 0 (=125)
1141221166:371502: rtc 464 int 125 0 (=125)
1141221166:871488: rtc 448 int 125 0 (=125)
1141221167:371476: rtc 464 int 125 0 (=125)
1141221167:871471: rtc 448 int 125 0 (=125)
1141221168:371451: rtc 464 int 125 0 (=125)
1141221168:871439: rtc 448 int 125 0 (=125)
1141221169:371427: rtc 464 int 125 0 (=125)
1141221169:871415: rtc 448 int 125 0 (=125)
1141221170:371402: rtc 464 int 125 0 (=125)
1141221170:871390: rtc 448 int 125 0 (=125)
1141221171:371377: rtc 464 int 125 0 (=125)
1141221171:871365: rtc 448 int 125 0 (=125)
1141221172:371352: rtc 464 int 125 0 (=125)
1141221172:875382: rtc 448 int 123 0 (=123) <-----
1141221173:375328: rtc 464 int 125 0 (=125)
1141221173:875340: rtc 448 int 125 0 (=125)
Kernel log highlights (idle=poll):
Kernel command line: ro root=/dev/md2 report_lost_ticks idle=poll
using polling idle threads.
...
time.c: Using 3.579545 MHz PM timer.
time.c: Detected 2009.264 MHz processor.
...
Using local APIC timer interrupts.
Detected 12.557 MHz APIC timer.
time.c: Lost 11 timer tick(s)! rip setup_boot_APIC_clock+0x117/0x11a)
Booting processor 1/2 APIC 0x1
Initializing CPU#1
Calibrating delay using timer specific routine.. 4018.82 BogoMIPS (lpj=8037642)
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 1024K (64 bytes/line)
CPU 1(1) -> Node 0 -> Core 0
AMD Opteron(tm) Processor 246 stepping 0a
CPU 1: Syncing TSC to CPU 0.
CPU 1: synchronized TSC with CPU 0 (last diff -129 cycles, maxerr 1112 cycles)
Brought up 2 CPUs
Disabling vsyscall due to use of PM timer
time.c: Using PM based timekeeping.
testing NMI watchdog ... <4>time.c: Lost 29 timer tick(s)! rip __delay+0x8/0x10)
OK.
...
powernow-k8: Found 2 AMD Athlon 64 / Opteron processors (version 1.50.4)
powernow-k8: MP systems not supported by PSB BIOS structure
powernow-k8: MP systems not supported by PSB BIOS structure
...
time.c: Lost 3 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 3 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 2 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 2 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 3 timer tick(s)! rip poll_idle+0xa/0x19)
Losing some ticks... checking if CPU frequency changed.
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 2 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 3 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 2 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0x14/0x19)
time.c: Lost 3 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 1 timer tick(s)! rip poll_idle+0xa/0x19)
time.c: Lost 2 timer tick(s)! rip poll_idle+0x14/0x19)
Thanks.
Bill
On Wednesday 01 March 2006 15:46, Bill Rugolsky Jr. wrote:
> On Wed, Mar 01, 2006 at 12:53:58AM +0100, Andi Kleen wrote:
> > What chipset?
>
> Thanks for the interest, Andi.
>
> The chipset is NVIDIA nForce Pro 2200 (CK804). The mobo is Tyan 2895:
I have such a system sitting next to me and it doesn't show any such symptoms.
I normally don't let it run unrebooted over days though.
I would suspect some driver.
Do you use any special addin cards? What modules are you using?
> http://www.tyan.com/products/html/thunderk8we.html
>
> It's running the current 1.02 version of the BIOS.
My BIOS is
Version: 2004Q3
Release Date: 06/07/2005
(which is self contradicting, but oh well)
> Current kernel is the FC4 errata:
I don't run these kernels though - only mainline.
> 1141220165:151240: rtc 464 int 0 125 (=125)
...
Looks all ok. Your timer interrupts are ticking correctly.
> time.c: Lost 3 timer tick(s)! rip poll_idle+0x14/0x19)
Ok then it's not C1.
-Andi
On Wed, Mar 01, 2006 at 03:56:09PM +0100, Andi Kleen wrote:
> > Thanks for the interest, Andi.
> >
> > The chipset is NVIDIA nForce Pro 2200 (CK804). The mobo is Tyan 2895:
>
> I have such a system sitting next to me and it doesn't show any such symptoms.
> I normally don't let it run unrebooted over days though.
These lost ticks are reproducable in a few minutes with cpio.
> I would suspect some driver.
> Do you use any special addin cards? What modules are you using?
My guess is the sata_nv driver, as it happens during heavy local file read.
The machines all have 2-4 SATA WD Raptors connected to the mobo.
> I don't run these kernels though - only mainline.
I wouldn't expect you to be running a Fedora kernel. :-p
I usually roll my own, but I've been really backed up with other tasks.
As I said, I'll build some mainline kernels. I want to apply
some of Ingo's debugging patches and give John Stultz's new timekeeping
code a try anyway.
rugolsky@ti94: cat /proc/interrupts
CPU0 CPU1
0: 28474 577049 IO-APIC-edge timer
1: 8 0 IO-APIC-edge i8042
7: 2 0 IO-APIC-edge parport0
8: 40 0 IO-APIC-edge rtc
9: 0 0 IO-APIC-level acpi
14: 36 21506 IO-APIC-edge ide0
50: 3 0 IO-APIC-level ohci1394
201: 0 0 IO-APIC-level libata, ehci_hcd:usb1
209: 1876 15495 IO-APIC-level libata, ohci_hcd:usb2
217: 2483567 0 IO-APIC-level eth0
233: 0 0 IO-APIC-level NVidia CK804
NMI: 87 41
LOC: 605510 605486
ERR: 0
MIS: 0
Lots-o-modules; I'll have to whittle these down.
rugolsky@ti94: lsmod
Module Size Used by
parport_pc 65581 1
lp 49025 0
parport 77261 2 parport_pc,lp
nfs 275745 4
lockd 107601 2 nfs
nfs_acl 37185 1 nfs
sunrpc 210041 4 nfs,lockd,nfs_acl
8021q 57041 0
video 52553 0
button 41185 0
battery 44233 0
ac 38985 0
ohci1394 71457 0
ieee1394 407641 1 ohci1394
ohci_hcd 57565 0
ehci_hcd 70477 0
i2c_nforce2 41409 0
i2c_core 59457 1 i2c_nforce2
snd_intel8x0 70889 0
snd_ac97_codec 146045 1 snd_intel8x0
snd_ac97_bus 36033 1 snd_ac97_codec
snd_seq_dummy 37445 0
snd_seq_oss 71973 0
snd_seq_midi_event 42177 1 snd_seq_oss
snd_seq 99225 5 snd_seq_dummy,snd_seq_oss,snd_seq_midi_event
snd_seq_device 43857 3 snd_seq_dummy,snd_seq_oss,snd_seq
snd_pcm_oss 93297 0
snd_mixer_oss 52673 1 snd_pcm_oss
snd_pcm 139593 3 snd_intel8x0,snd_ac97_codec,snd_pcm_oss
snd_timer 62025 2 snd_seq,snd_pcm
snd 103073 9 snd_intel8x0,snd_ac97_codec,snd_seq_oss,snd_seq,
snd_seq_device,snd_pcm_oss,snd_mixer_oss,snd_pcm,snd_timer
soundcore 45025 1 snd
snd_page_alloc 46289 2 snd_intel8x0,snd_pcm
forcedeth 60869 0
floppy 107993 0
ext3 179665 5
jbd 100073 1 ext3
raid1 56385 4
dm_mod 98697 4
sata_nv 44101 8
libata 98265 1 sata_nv
sd_mod 53697 10
scsi_mod 195321 2 libata,sd_mod
Thanks.
-Bill
On Wednesday 01 March 2006 16:43, Bill Rugolsky Jr. wrote:
> > I would suspect some driver.
> > Do you use any special addin cards? What modules are you using?
>
> My guess is the sata_nv driver, as it happens during heavy local file read.
> The machines all have 2-4 SATA WD Raptors connected to the mobo.
Are you accessing all these disks in parallel with that cpio? If
yes could you try it with only a single disk?
My box only has a single SATA disk. Maybe there is some
corner case in that SATA driver that leaks interrupt state
and it's only turned on later by idle or softirq then.
-Andi
On Wed, Mar 01, 2006 at 04:47:33PM +0100, Andi Kleen wrote:
> > My guess is the sata_nv driver, as it happens during heavy local file read.
> > The machines all have 2-4 SATA WD Raptors connected to the mobo.
>
> Are you accessing all these disks in parallel with that cpio? If
> yes could you try it with only a single disk?
Yes, all of the hosts are LVM2 over MD RAID1. The PostgreSQL
LV has striping over the two MD RAID1 PVs.
> My box only has a single SATA disk. Maybe there is some
> corner case in that SATA driver that leaks interrupt state
> and it's only turned on later by idle or softirq then.
Good call! Stressing one disk results in no lost ticks.
I stuck a spare disk in one of the workstations that has its system
partitions on Ext3/LVM2/MD-RAID1, and then copied the 9GB /usr to
a raw Ext3 partition on the new disk:
find usr | cpio -pdum /opt
That resulted in:
Mar 1 11:39:27 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:39:41 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:37 ti94 kernel: time.c: Lost 3 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:40 ti94 kernel: time.c: Lost 6 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:41 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:42 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:50 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:54 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:40:57 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:01 ti94 kernel: time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:06 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:12 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:17 ti94 kernel: time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:21 ti94 kernel: time.c: Lost 3 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:27 ti94 kernel: time.c: Lost 4 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:27 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:29 ti94 kernel: time.c: Lost 3 timer tick(s)! rip _spin_unlock_irqrestore+0xb/0xd)
Mar 1 11:41:42 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:43 ti94 kernel: time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:43 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:46 ti94 kernel: time.c: Lost 2 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:55 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Mar 1 11:41:55 ti94 kernel: time.c: Lost 2 timer tick(s)! rip default_idle+0x37/0x7a)
Mar 1 11:41:57 ti94 kernel: time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
Mar 1 11:41:57 ti94 kernel: time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
Mar 1 11:42:00 ti94 kernel: time.c: Lost 2 timer tick(s)! rip default_idle+0x37/0x7a)
Mar 1 11:42:00 ti94 kernel: time.c: Lost 1 timer tick(s)! rip default_idle+0x37/0x7a)
Mar 1 11:42:00 ti94 kernel: time.c: Lost 2 timer tick(s)! rip default_idle+0x37/0x7a)
...
After a umount/mount on /opt, I did
find /opt | cpio -o > /dev/null
and got no lost ticks in the log. My "nice --10 ./trtc" gave me:
rugolsky@ti94: tail +10 one-disk | grep -v '=125'
1141232738:578610: rtc 448 int 124 0 (=124)
1141232807:67036: rtc 464 int 0 124 (=124)
1141232875:557669: rtc 448 int 0 124 (=124)
I converted the raw EXT3 partition to a degraded MD RAID1, and again
got no lost ticks. Then I created a PV/VG/LV/Ext3 on top of the degraded MD RAID1,
populated it, and re-read it; once again, there were no lost ticks on the
single-disk read.
Time to instrument sata_nv, I suppose. Many thanks for helping to narrow this
down.
-Bill
On Wednesday 01 March 2006 19:07, Bill Rugolsky Jr. wrote:
> Mar 1 11:39:27 ti94 kernel: time.c: Lost 1 timer tick(s)! rip __do_softirq+0x55/0xd4)
Yes, I bet something forgets to turn on interrupts again and it's picked up by
(and blamed on) the next guy who does an unconditional sti, which happens to be __do_sofitrq
or idle.
> Time to instrument sata_nv, I suppose. Many thanks for helping to narrow this
> down.
Sprinkle WARN_ON(in_interrupt()) all over the parts that shouldn't have interrupts
off.
-Andi
On Wed, 2006-03-01 at 19:29 +0100, Andi Kleen wrote:
> Sprinkle WARN_ON(in_interrupt()) all over the parts that shouldn't
> have interrupts
> off.
Might be faster to just try the -rt kernel, it has tons of debugging
checks for stuff like this.
Lee
On Wed, Mar 01, 2006 at 10:43:13AM -0500, Bill Rugolsky Jr. wrote:
> My guess is the sata_nv driver, as it happens during heavy local file read.
> The machines all have 2-4 SATA WD Raptors connected to the mobo.
I have 4 SATA disks connected to an nForce4, being part of an md/raid5
array. If I start bonnie on the raid5 array, I get:
warning: many lost ticks.
Your time source seems to be instable or some driver is hogging interupts
rip __do_softirq+0x3b/0xa1
So sata_nv definitely looks fishy.
Gabor
--
---------------------------------------------------------
MTA SZTAKI Computer and Automation Research Institute
Hungarian Academy of Sciences
---------------------------------------------------------
On Wed, Mar 01, 2006 at 02:16:50PM -0500, Lee Revell wrote:
> On Wed, 2006-03-01 at 19:29 +0100, Andi Kleen wrote:
> > Sprinkle WARN_ON(in_interrupt()) all over the parts that shouldn't
> > have interrupts
> > off.
>
> Might be faster to just try the -rt kernel, it has tons of debugging
> checks for stuff like this.
After several attempts where 2.6.15-rt18 reset on startup, I whittled
my config down to something minimal (turned off NUMA, CPUSETS, PRINTK_TIME, ...)
and got it up and running PREEMPT_RT:
rugolsky@ti94: uname -a
Linux ti94 2.6.15-rt18-realtime #4 SMP PREEMPT Fri Mar 3 11:39:20 EST 2006 x86_64 x86_64 x86_64 GNU/Linux
rugolsky@ti94: egrep 'PREEMPT|LATENCY|HZ' .config
# CONFIG_PREEMPT_NONE is not set
# CONFIG_PREEMPT_VOLUNTARY is not set
# CONFIG_PREEMPT_DESKTOP is not set
CONFIG_PREEMPT_RT=y
CONFIG_PREEMPT=y
CONFIG_PREEMPT_SOFTIRQS=y
CONFIG_PREEMPT_HARDIRQS=y
CONFIG_PREEMPT_BKL=y
CONFIG_PREEMPT_RCU=y
# CONFIG_HZ_100 is not set
# CONFIG_HZ_250 is not set
CONFIG_HZ_1000=y
CONFIG_HZ=1000
CONFIG_DEBUG_PREEMPT=y
# CONFIG_WAKEUP_LATENCY_HIST is not set
CONFIG_PREEMPT_TRACE=y
CONFIG_CRITICAL_PREEMPT_TIMING=y
# CONFIG_PREEMPT_OFF_HIST is not set
CONFIG_LATENCY_TIMING=y
CONFIG_LATENCY_TRACE=y
% sudo sysctl -a | egrep 'kernel\.*(preempt|latency|trace|wakeup)'
kernel.preempt_thresh = 0
kernel.preempt_max_latency = 2483
kernel.trace_all_cpus = 1
kernel.trace_verbose = 1
kernel.trace_print_at_crash = 1
kernel.trace_freerunning = 0
kernel.trace_user_trigger_irq = -1
kernel.trace_user_trigger_irq = -1
kernel.trace_user_triggered = 0
kernel.trace_enabled = 1
kernel.wakeup_timing = 1
% cat /sys/devices/system/clocksource/clocksource0/current_clocksource
acpi_pm
Should I be compiling for a different preempt mode? I've only cursorily
followed the realtime-preempt patch discussion threads, so I am unclear as
to what debugging facilities are available with each preemption level.
[Is there a howto/tutorial floating around on using the debugging
features?]
I got the following trace. Since you have a great deal of experience
interpreting these traces, perhaps you can help me interpret this one?
Thanks.
Bill Rugolsky
preemption latency trace v1.1.5 on 2.6.15-rt18-realtime
--------------------------------------------------------------------
latency: 2483 us, #238/238, CPU#1 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-----------------
| task: softirq-timer/1-14 (uid:0 nice:0 policy:1 rt_prio:1)
-----------------
(T1/#0) <...> 697 0 16 00000000 00000000 [00000424e86874c5] 0.000ms (+0.000ms): smp_apic_timer_interrupt+0xc/0x48 <ffffffff8011902a> (apic_timer_interrupt+0x84/0x8c <ffffffff8010ead0>)
(T1/#1) <...> 697 0 20 00000000 00000001 [00000424e86876a8] 0.000ms (+0.000ms): smp_local_timer_interrupt+0xc/0x32 <ffffffff80118ad5> (smp_apic_timer_interrupt+0x3e/0x48 <ffffffff8011905c>)
(T1/#2) <...> 697 0 20 00000000 00000002 [00000424e868778c] 0.000ms (+0.000ms): profile_tick+0xc/0x77 <ffffffff801334d4> (smp_local_timer_interrupt+0x1c/0x32 <ffffffff80118ae5>)
(T1/#3) <...> 697 0 20 00000000 00000003 [00000424e8687885] 0.000ms (+0.000ms): profile_pc+0xc/0x71 <ffffffff8011173c> (profile_tick+0x67/0x77 <ffffffff8013352f>)
(T1/#4) <...> 697 0 20 00000000 00000004 [00000424e86879a4] 0.000ms (+0.000ms): profile_hit+0x14/0x19f <ffffffff8013333d> (profile_tick+0x72/0x77 <ffffffff8013353a>)
(T1/#5) <...> 697 0 20 00000000 00000005 [00000424e8687aae] 0.000ms (+0.000ms): update_process_times+0xc/0x68 <ffffffff8013b457> (smp_local_timer_interrupt+0x2e/0x32 <ffffffff80118af7>)
(T1/#6) <...> 697 0 20 00000000 00000006 [00000424e8687baf] 0.000ms (+0.000ms): account_system_time+0x9/0x9e <ffffffff8012a19c> (update_process_times+0x3f/0x68 <ffffffff8013b48a>)
(T1/#7) <...> 697 0 20 00000000 00000007 [00000424e8687cb0] 0.001ms (+0.000ms): acct_update_integrals+0x9/0x59 <ffffffff801571a1> (account_system_time+0x9c/0x9e <ffffffff8012a22f>)
(T1/#8) <...> 697 0 20 00000000 00000008 [00000424e8687dca] 0.001ms (+0.000ms): run_local_timers+0x9/0x15 <ffffffff8013b0cd> (update_process_times+0x44/0x68 <ffffffff8013b48f>)
(T1/#9) <...> 697 0 20 00000000 00000009 [00000424e8687ea7] 0.001ms (+0.000ms): raise_softirq+0xc/0x91 <ffffffff80137cf8> (run_local_timers+0x13/0x15 <ffffffff8013b0d7>)
(T1/#10) <...> 697 0 20 00000000 0000000a [00000424e8687fce] 0.001ms (+0.000ms): wakeup_softirqd+0x9/0x38 <ffffffff801373e5> (raise_softirq+0x6f/0x91 <ffffffff80137d5b>)
(T1/#11) <...> 697 0 20 00000000 0000000b [00000424e86880c5] 0.001ms (+0.000ms): wake_up_process+0xb/0x31 <ffffffff8012cd66> (wakeup_softirqd+0x36/0x38 <ffffffff80137412>)
(T1/#12) <...> 697 0 20 00000000 0000000c [00000424e86881ab] 0.001ms (+0.000ms): check_preempt_wakeup+0xc/0xac <ffffffff8014a814> (wake_up_process+0x13/0x31 <ffffffff8012cd6e>)
(T1/#13) <...> 697 0 20 00000000 0000000d [00000424e86882b4] 0.001ms (+0.000ms): try_to_wake_up+0x16/0x560 <ffffffff8012c747> (wake_up_process+0x24/0x31 <ffffffff8012cd7f>)
(T1/#14) <...> 697 0 20 00000000 0000000e [00000424e86883ad] 0.001ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (try_to_wake_up+0x5d/0x560 <ffffffff8012c78e>)
(T1/#15) <...> 697 0 20 00000001 0000000f [00000424e86884fd] 0.002ms (+0.000ms): idle_cpu+0x9/0x30 <ffffffff80129d37> (try_to_wake_up+0x292/0x560 <ffffffff8012c9c3>)
(T1/#16) <idle> 0 1 23 00000003 00000010 [00000424e86885b5] 0.002ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (unmask_IO_APIC_irq+0x35/0x3a <ffffffff8011a854>)
(T1/#17) <...> 697 0 20 00000001 00000011 [00000424e868868b] 0.002ms (+0.000ms): smp_send_reschedule_allbutself+0x9/0x1a <ffffffff8011809b> (try_to_wake_up+0x3e9/0x560 <ffffffff8012cb1a>)
(T1/#18) <idle> 0 1 23 00000002 00000012 [00000424e86886b0] 0.002ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
(T1/#19) <...> 697 0 20 00000001 00000013 [00000424e8688779] 0.002ms (+0.000ms): flat_send_IPI_allbutself+0xb/0x5b <ffffffff8011b644> (smp_send_reschedule_allbutself+0x18/0x1a <ffffffff801180aa>)
(T1/#20) <idle> 0 1 23 00000002 00000014 [00000424e86887ba] 0.002ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
(T1/#21) <...> 697 0 20 00000001 00000015 [00000424e8688855] 0.002ms (+0.000ms): __bitmap_weight+0xa/0x18b <ffffffff801fbce6> (flat_send_IPI_allbutself+0x1e/0x5b <ffffffff8011b657>)
(T1/#22) <idle> 0 1 23 00000002 00000016 [00000424e86888ab] 0.002ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock_irqrestore+0x5e/0x62 <ffffffff802fa670>)
(T1/#23) <idle> 0 1 23 00000002 00000017 [00000424e86889c7] 0.002ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0x12a/0x141 <ffffffff8015deb9>)
(T1/#24) <...> 697 0 20 00000001 00000018 [00000424e8688a6c] 0.002ms (+0.000ms): activate_task+0x10/0xe0 <ffffffff8012bc38> (try_to_wake_up+0x491/0x560 <ffffffff8012cbc2>)
(T1/#25) <idle> 0 1 23 00000001 00000019 [00000424e8688abd] 0.002ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#26) <...> 697 0 20 00000001 0000001a [00000424e8688b4b] 0.002ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (activate_task+0x1d/0xe0 <ffffffff8012bc45>)
(T1/#27) <idle> 0 1 23 00000001 0000001b [00000424e8688bbc] 0.002ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
(T3/#28) <...>-697 0D.h1 2us : activate_task+0x9b/0xe0 <ffffffff8012bcc3> <<...>-4> (62 1)
(T1/#29) <idle> 0 1 23 00000001 0000001d [00000424e8688cd8] 0.003ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (do_IRQ+0x3a/0x44 <ffffffff80110767>)
(T1/#30) <...> 697 0 20 00000001 0000001e [00000424e8688d26] 0.003ms (+0.000ms): enqueue_task+0xc/0x95 <ffffffff80129be4> (activate_task+0xa7/0xe0 <ffffffff8012bccf>)
(T1/#31) <...> 697 0 20 00000001 0000001f [00000424e8688f26] 0.003ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (try_to_wake_up+0x54f/0x560 <ffffffff8012cc80>)
(T1/#32) <idle> 0 1 19 00000001 00000020 [00000424e8688f9e] 0.003ms (+0.000ms): smp_reschedule_interrupt+0x9/0x16 <ffffffff801186ee> (reschedule_interrupt+0x84/0x8c <ffffffff8010e558>)
(T1/#33) <...> 697 0 20 00000000 00000021 [00000424e868901e] 0.003ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
(T1/#34) <...> 697 0 20 00000000 00000022 [00000424e8689137] 0.003ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
(T1/#35) <idle> 0 1 19 00000001 00000023 [00000424e8689211] 0.003ms (+0.000ms): smp_apic_timer_interrupt+0xc/0x48 <ffffffff8011902a> (apic_timer_interrupt+0x84/0x8c <ffffffff8010ead0>)
(T1/#36) <...> 697 0 20 00000000 00000024 [00000424e8689254] 0.003ms (+0.000ms): wake_up_process+0x2b/0x31 <ffffffff8012cd86> (wakeup_softirqd+0x36/0x38 <ffffffff80137412>)
(T1/#37) <...> 697 0 20 00000000 00000025 [00000424e8689354] 0.003ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (raise_softirq+0x77/0x91 <ffffffff80137d63>)
(T1/#38) <idle> 0 1 23 00000001 00000026 [00000424e8689354] 0.003ms (+0.000ms): smp_local_timer_interrupt+0xc/0x32 <ffffffff80118ad5> (smp_apic_timer_interrupt+0x3e/0x48 <ffffffff8011905c>)
(T1/#39) <idle> 0 1 23 00000001 00000027 [00000424e8689426] 0.003ms (+0.000ms): profile_tick+0xc/0x77 <ffffffff801334d4> (smp_local_timer_interrupt+0x1c/0x32 <ffffffff80118ae5>)
(T1/#40) <...> 697 0 20 00000000 00000028 [00000424e8689492] 0.004ms (+0.000ms): rcu_pending+0x9/0x30 <ffffffff801445e8> (update_process_times+0x4b/0x68 <ffffffff8013b496>)
(T1/#41) <idle> 0 1 23 00000001 00000029 [00000424e8689520] 0.004ms (+0.000ms): profile_pc+0xc/0x71 <ffffffff8011173c> (profile_tick+0x67/0x77 <ffffffff8013352f>)
(T1/#42) <...> 697 0 20 00000000 0000002a [00000424e86895c8] 0.004ms (+0.000ms): scheduler_tick+0x13/0x34c <ffffffff8012d1b9> (update_process_times+0x5e/0x68 <ffffffff8013b4a9>)
(T1/#43) <idle> 0 1 23 00000001 0000002b [00000424e8689636] 0.004ms (+0.000ms): profile_hit+0x14/0x19f <ffffffff8013333d> (profile_tick+0x72/0x77 <ffffffff8013353a>)
(T1/#44) <...> 697 0 20 00000000 0000002c [00000424e86896af] 0.004ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (scheduler_tick+0x3d/0x34c <ffffffff8012d1e3>)
(T1/#45) <idle> 0 1 23 00000001 0000002d [00000424e8689754] 0.004ms (+0.000ms): update_process_times+0xc/0x68 <ffffffff8013b457> (smp_local_timer_interrupt+0x2e/0x32 <ffffffff80118af7>)
(T1/#46) <...> 697 0 20 00000000 0000002e [00000424e86897c5] 0.004ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (scheduler_tick+0xce/0x34c <ffffffff8012d274>)
(T1/#47) <idle> 0 1 23 00000001 0000002f [00000424e868984a] 0.004ms (+0.000ms): account_system_time+0x9/0x9e <ffffffff8012a19c> (update_process_times+0x3f/0x68 <ffffffff8013b48a>)
(T1/#48) <...> 697 0 20 00000001 00000030 [00000424e86898f8] 0.004ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (scheduler_tick+0x330/0x34c <ffffffff8012d4d6>)
(T1/#49) <idle> 0 1 23 00000001 00000031 [00000424e868994c] 0.004ms (+0.000ms): acct_update_integrals+0x9/0x59 <ffffffff801571a1> (account_system_time+0x9c/0x9e <ffffffff8012a22f>)
(T1/#50) <...> 697 0 20 00000000 00000032 [00000424e8689a04] 0.004ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#51) <idle> 0 1 23 00000001 00000033 [00000424e8689a5a] 0.004ms (+0.000ms): run_local_timers+0x9/0x15 <ffffffff8013b0cd> (update_process_times+0x44/0x68 <ffffffff8013b48f>)
(T1/#52) <...> 697 0 20 00000000 00000034 [00000424e8689b0b] 0.004ms (+0.000ms): rebalance_tick+0x16/0x2e8 <ffffffff8012ced4> (scheduler_tick+0x340/0x34c <ffffffff8012d4e6>)
(T1/#53) <idle> 0 1 23 00000001 00000035 [00000424e8689b36] 0.004ms (+0.000ms): raise_softirq+0xc/0x91 <ffffffff80137cf8> (run_local_timers+0x13/0x15 <ffffffff8013b0d7>)
(T1/#54) <idle> 0 1 23 00000001 00000036 [00000424e8689c41] 0.005ms (+0.000ms): wakeup_softirqd+0x9/0x38 <ffffffff801373e5> (raise_softirq+0x6f/0x91 <ffffffff80137d5b>)
(T1/#55) <idle> 0 1 23 00000001 00000037 [00000424e8689d50] 0.005ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (raise_softirq+0x77/0x91 <ffffffff80137d63>)
(T1/#56) <...> 697 0 20 00000000 00000038 [00000424e8689dc9] 0.005ms (+0.000ms): softlockup_tick+0xf/0x11d <ffffffff8015d672> (update_process_times+0x63/0x68 <ffffffff8013b4ae>)
(T1/#57) <idle> 0 1 23 00000001 00000039 [00000424e8689e81] 0.005ms (+0.000ms): rcu_pending+0x9/0x30 <ffffffff801445e8> (update_process_times+0x4b/0x68 <ffffffff8013b496>)
(T1/#58) <...> 697 0 20 00000000 0000003a [00000424e8689ef2] 0.005ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (smp_apic_timer_interrupt+0x43/0x48 <ffffffff80119061>)
(T1/#59) <idle> 0 1 23 00000001 0000003b [00000424e8689f91] 0.005ms (+0.000ms): scheduler_tick+0x13/0x34c <ffffffff8012d1b9> (update_process_times+0x5e/0x68 <ffffffff8013b4a9>)
(T1/#60) <idle> 0 1 23 00000001 0000003c [00000424e868a078] 0.005ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (scheduler_tick+0x3d/0x34c <ffffffff8012d1e3>)
(T1/#61) <idle> 0 1 23 00000001 0000003d [00000424e868a17d] 0.005ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (scheduler_tick+0x81/0x34c <ffffffff8012d227>)
(T1/#62) <...> 697 0 16 00000000 0000003e [00000424e868a1e5] 0.005ms (+0.000ms): do_IRQ+0xc/0x44 <ffffffff80110739> (ret_from_intr+0x0/0x12 <ffffffff8010e276>)
(T1/#63) <idle> 0 1 23 00000002 0000003f [00000424e868a2cf] 0.005ms (+0.000ms): resched_task+0xc/0x79 <ffffffff8012a958> (scheduler_tick+0x95/0x34c <ffffffff8012d23b>)
(T1/#64) <...> 697 0 20 00000000 00000040 [00000424e868a332] 0.005ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (__do_IRQ+0x5d/0x141 <ffffffff8015ddec>)
(T1/#65) <idle> 0 1 23 00000002 00000041 [00000424e868a3e6] 0.006ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (scheduler_tick+0x9d/0x34c <ffffffff8012d243>)
(T1/#66) <...> 697 0 20 00000001 00000042 [00000424e868a469] 0.006ms (+0.000ms): mask_and_ack_level_ioapic_irq+0x10/0xa2 <ffffffff8011aa2d> (__do_IRQ+0x72/0x141 <ffffffff8015de01>)
(T1/#67) <idle> 0 1 23 00000001 00000043 [00000424e868a4e0] 0.006ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#68) <...> 697 0 20 00000001 00000044 [00000424e868a548] 0.006ms (+0.000ms): mask_IO_APIC_irq+0xb/0x11e <ffffffff8011a90a> (mask_and_ack_level_ioapic_irq+0x8e/0xa2 <ffffffff8011aaab>)
(T1/#69) <idle> 0 1 23 00000001 00000045 [00000424e868a5e8] 0.006ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
(T1/#70) <...> 697 0 20 00000001 00000046 [00000424e868a6bd] 0.006ms (+0.000ms): _raw_spin_lock_irqsave+0xc/0x33 <ffffffff802fa2ab> (mask_IO_APIC_irq+0x19/0x11e <ffffffff8011a918>)
(T1/#71) <idle> 0 1 23 00000001 00000047 [00000424e868a70c] 0.006ms (+0.000ms): rebalance_tick+0x16/0x2e8 <ffffffff8012ced4> (scheduler_tick+0x340/0x34c <ffffffff8012d4e6>)
(T1/#72) <idle> 0 1 23 00000001 00000048 [00000424e868a936] 0.006ms (+0.000ms): softlockup_tick+0xf/0x11d <ffffffff8015d672> (update_process_times+0x63/0x68 <ffffffff8013b4ae>)
(T1/#73) <idle> 0 1 23 00000001 00000049 [00000424e868aa5e] 0.006ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (smp_apic_timer_interrupt+0x43/0x48 <ffffffff80119061>)
(T1/#74) <idle> 0 1 19 00000001 0000004a [00000424e868ad2f] 0.007ms (+0.000ms): do_IRQ+0xc/0x44 <ffffffff80110739> (ret_from_intr+0x0/0x12 <ffffffff8010e276>)
(T1/#75) <idle> 0 1 23 00000001 0000004b [00000424e868ae68] 0.007ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (__do_IRQ+0x5d/0x141 <ffffffff8015ddec>)
(T1/#76) <idle> 0 1 23 00000002 0000004c [00000424e868b067] 0.007ms (+0.000ms): ack_edge_ioapic_irq+0x10/0xba <ffffffff8011ab21> (__do_IRQ+0x72/0x141 <ffffffff8015de01>)
(T1/#77) <idle> 0 1 23 00000002 0000004d [00000424e868b16b] 0.007ms (+0.000ms): redirect_hardirq+0x9/0x53 <ffffffff8015d909> (__do_IRQ+0xb5/0x141 <ffffffff8015de44>)
(T1/#78) <idle> 0 1 23 00000002 0000004e [00000424e868b283] 0.007ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0xc1/0x141 <ffffffff8015de50>)
(T1/#79) <idle> 0 1 23 00000001 0000004f [00000424e868b38d] 0.007ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#80) <idle> 0 1 23 00000001 00000050 [00000424e868b4a0] 0.008ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
(T1/#81) <idle> 0 1 23 00000001 00000051 [00000424e868b5af] 0.008ms (+0.000ms): handle_IRQ_event+0x16/0x114 <ffffffff8015d96f> (__do_IRQ+0xd1/0x141 <ffffffff8015de60>)
(T1/#82) <idle> 0 1 23 00000001 00000052 [00000424e868b699] 0.008ms (+0.000ms): timer_interrupt+0xb/0x62 <ffffffff801117ac> (handle_IRQ_event+0x6a/0x114 <ffffffff8015d9c3>)
(T1/#83) <idle> 0 1 23 00000001 00000053 [00000424e868b789] 0.008ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (timer_interrupt+0x1a/0x62 <ffffffff801117bb>)
(T1/#84) <idle> 0 1 23 00000002 00000054 [00000424e868b8c5] 0.008ms (+0.000ms): do_timer+0x9/0x12 <ffffffff8013b0e2> (timer_interrupt+0x28/0x62 <ffffffff801117c9>)
(T1/#85) <idle> 0 1 23 00000002 00000055 [00000424e868ba17] 0.008ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (timer_interrupt+0x4b/0x62 <ffffffff801117ec>)
(T1/#86) <...> 697 0 20 00000002 00000056 [00000424e868ba4b] 0.008ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (mask_IO_APIC_irq+0x11a/0x11e <ffffffff8011aa19>)
(T1/#87) <idle> 0 1 23 00000001 00000057 [00000424e868bb18] 0.008ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#88) <...> 697 0 20 00000001 00000058 [00000424e868bb4d] 0.008ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
(T1/#89) <idle> 0 1 23 00000001 00000059 [00000424e868bc15] 0.009ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
(T1/#90) <...> 697 0 20 00000001 0000005a [00000424e868bc62] 0.009ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
(T1/#91) <idle> 0 1 23 00000001 0000005b [00000424e868bd30] 0.009ms (+0.000ms): smp_send_timer_broadcast_ipi+0x9/0x31 <ffffffff80118a91> (timer_interrupt+0x59/0x62 <ffffffff801117fa>)
(T1/#92) <...> 697 0 20 00000001 0000005c [00000424e868bd98] 0.009ms (+0.000ms): redirect_hardirq+0x9/0x53 <ffffffff8015d909> (__do_IRQ+0xb5/0x141 <ffffffff8015de44>)
(T1/#93) <idle> 0 1 23 00000001 0000005d [00000424e868be66] 0.009ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (__do_IRQ+0xdb/0x141 <ffffffff8015de6a>)
(T1/#94) <...> 697 0 20 00000001 0000005e [00000424e868bed0] 0.009ms (+0.000ms): wake_up_process+0xb/0x31 <ffffffff8012cd66> (redirect_hardirq+0x46/0x53 <ffffffff8015d946>)
(T1/#95) <idle> 0 1 23 00000002 0000005f [00000424e868bfa8] 0.009ms (+0.000ms): note_interrupt+0x16/0x227 <ffffffff8015ec77> (__do_IRQ+0xf5/0x141 <ffffffff8015de84>)
(T1/#96) <...> 697 0 20 00000001 00000060 [00000424e868bfe2] 0.009ms (+0.000ms): check_preempt_wakeup+0xc/0xac <ffffffff8014a814> (wake_up_process+0x13/0x31 <ffffffff8012cd6e>)
(T1/#97) <idle> 0 1 23 00000002 00000061 [00000424e868c0a8] 0.009ms (+0.000ms): unmask_IO_APIC_irq+0xc/0x3a <ffffffff8011a82b> (__do_IRQ+0x122/0x141 <ffffffff8015deb1>)
(T1/#98) <...> 697 0 20 00000001 00000062 [00000424e868c0d6] 0.009ms (+0.000ms): try_to_wake_up+0x16/0x560 <ffffffff8012c747> (wake_up_process+0x24/0x31 <ffffffff8012cd7f>)
(T1/#99) <idle> 0 1 23 00000002 00000063 [00000424e868c19a] 0.009ms (+0.000ms): _raw_spin_lock_irqsave+0xc/0x33 <ffffffff802fa2ab> (unmask_IO_APIC_irq+0x1b/0x3a <ffffffff8011a83a>)
(T1/#100) <...> 697 0 20 00000001 00000064 [00000424e868c1f8] 0.009ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (try_to_wake_up+0x5d/0x560 <ffffffff8012c78e>)
(T1/#101) <...> 697 0 20 00000002 00000065 [00000424e868c3d9] 0.010ms (+0.000ms): idle_cpu+0x9/0x30 <ffffffff80129d37> (try_to_wake_up+0x292/0x560 <ffffffff8012c9c3>)
(T1/#102) <idle> 0 1 23 00000003 00000066 [00000424e868c439] 0.010ms (+0.000ms): __unmask_IO_APIC_irq+0x9/0xff <ffffffff8011a729> (unmask_IO_APIC_irq+0x26/0x3a <ffffffff8011a845>)
(T1/#103) <...> 697 0 20 00000002 00000067 [00000424e868c538] 0.010ms (+0.000ms): smp_send_reschedule_allbutself+0x9/0x1a <ffffffff8011809b> (try_to_wake_up+0x3e9/0x560 <ffffffff8012cb1a>)
(T1/#104) <...> 697 0 20 00000002 00000068 [00000424e868c674] 0.010ms (+0.000ms): flat_send_IPI_allbutself+0xb/0x5b <ffffffff8011b644> (smp_send_reschedule_allbutself+0x18/0x1a <ffffffff801180aa>)
(T1/#105) <...> 697 0 20 00000002 00000069 [00000424e868c74e] 0.010ms (+0.000ms): __bitmap_weight+0xa/0x18b <ffffffff801fbce6> (flat_send_IPI_allbutself+0x1e/0x5b <ffffffff8011b657>)
(T1/#106) <...> 697 0 20 00000002 0000006a [00000424e868c95a] 0.010ms (+0.000ms): activate_task+0x10/0xe0 <ffffffff8012bc38> (try_to_wake_up+0x491/0x560 <ffffffff8012cbc2>)
(T1/#107) <...> 697 0 20 00000002 0000006b [00000424e868ca36] 0.010ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (activate_task+0x1d/0xe0 <ffffffff8012bc45>)
(T3/#108) <...>-697 0D.h2 11us : activate_task+0x9b/0xe0 <ffffffff8012bcc3> <<...>-1432> (3a 2)
(T1/#109) <...> 697 0 20 00000002 0000006d [00000424e868cc15] 0.011ms (+0.000ms): enqueue_task+0xc/0x95 <ffffffff80129be4> (activate_task+0xa7/0xe0 <ffffffff8012bccf>)
(T1/#110) <...> 697 0 20 00000002 0000006e [00000424e868cdf1] 0.011ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (try_to_wake_up+0x54f/0x560 <ffffffff8012cc80>)
(T1/#111) <...> 697 0 20 00000001 0000006f [00000424e868cf1a] 0.011ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
(T1/#112) <...> 697 0 20 00000001 00000070 [00000424e868d02f] 0.011ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
(T1/#113) <...> 697 0 20 00000001 00000071 [00000424e868d147] 0.011ms (+0.000ms): wake_up_process+0x2b/0x31 <ffffffff8012cd86> (redirect_hardirq+0x46/0x53 <ffffffff8015d946>)
(T1/#114) <...> 697 0 20 00000001 00000072 [00000424e868d261] 0.011ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0x12a/0x141 <ffffffff8015deb9>)
(T1/#115) <...> 697 0 20 00000000 00000073 [00000424e868d356] 0.012ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#116) <...> 697 0 20 00000000 00000074 [00000424e868d470] 0.012ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (do_IRQ+0x3a/0x44 <ffffffff80110767>)
(T1/#117) <...> 697 0 0 00000000 00000075 [00000424e868d72e] 0.012ms (+0.000ms): ata_host_intr+0xf/0xb6 <ffffffff88033d99> (nv_interrupt+0x65/0xa6 <ffffffff88042065>)
(T1/#118) <...> 697 0 0 00000000 00000076 [00000424e868d81d] 0.012ms (+0.000ms): ata_bmdma_status+0x9/0x27 <ffffffff88031e66> (ata_host_intr+0x3e/0xb6 <ffffffff88033dc8>)
(T1/#119) <idle> 0 1 23 00000003 00000077 [00000424e868d846] 0.012ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (unmask_IO_APIC_irq+0x35/0x3a <ffffffff8011a854>)
(T1/#120) <idle> 0 1 23 00000002 00000078 [00000424e868d958] 0.012ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
(T1/#121) <idle> 0 1 23 00000002 00000079 [00000424e868da62] 0.012ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
(T1/#122) <...> 697 0 0 00000000 0000007a [00000424e868dacb] 0.012ms (+0.000ms): ata_bmdma_stop+0x9/0x32 <ffffffff88031e34> (ata_host_intr+0x52/0xb6 <ffffffff88033ddc>)
(T1/#123) <idle> 0 1 23 00000002 0000007b [00000424e868db53] 0.013ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock_irqrestore+0x5e/0x62 <ffffffff802fa670>)
(T1/#124) <idle> 0 1 23 00000002 0000007c [00000424e868dc6f] 0.013ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0x12a/0x141 <ffffffff8015deb9>)
(T1/#125) <idle> 0 1 23 00000001 0000007d [00000424e868dd65] 0.013ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#126) <idle> 0 1 23 00000001 0000007e [00000424e868de78] 0.013ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
(T1/#127) <...> 697 0 0 00000000 0000007f [00000424e868dec3] 0.013ms (+0.000ms): ata_altstatus+0x9/0x34 <ffffffff88031e00> (ata_bmdma_stop+0x30/0x32 <ffffffff88031e5b>)
(T1/#128) <idle> 0 1 23 00000001 00000080 [00000424e868df94] 0.013ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (do_IRQ+0x3a/0x44 <ffffffff80110767>)
(T1/#129) <...> 697 0 0 00000000 00000081 [00000424e868e150] 0.013ms (+0.000ms): ata_altstatus+0x9/0x34 <ffffffff88031e00> (ata_host_intr+0x5a/0xb6 <ffffffff88033de4>)
(T1/#130) <idle> 0 1 19 00000001 00000082 [00000424e868e25a] 0.013ms (+0.000ms): smp_reschedule_interrupt+0x9/0x16 <ffffffff801186ee> (reschedule_interrupt+0x84/0x8c <ffffffff8010e558>)
(T1/#131) <...> 697 0 0 00000000 00000083 [00000424e868e3d5] 0.014ms (+0.000ms): ata_check_status+0x9/0x23 <ffffffff88031ddd> (ata_host_intr+0x68/0xb6 <ffffffff88033df2>)
(T1/#132) <idle> 0 1 19 00000000 00000084 [00000424e868e465] 0.014ms (+0.000ms): __schedule+0x16/0xad6 <ffffffff802f7609> (cpu_idle+0xbe/0xd3 <ffffffff8010c6dd>)
(T1/#133) <idle> 0 1 19 00000000 00000085 [00000424e868e560] 0.014ms (+0.000ms): profile_hit+0x14/0x19f <ffffffff8013333d> (__schedule+0xb0/0xad6 <ffffffff802f76a3>)
(T1/#134) <idle> 0 1 19 00000001 00000086 [00000424e868e6a4] 0.014ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (__schedule+0x110/0xad6 <ffffffff802f7703>)
(T1/#135) <...> 697 0 0 00000000 00000087 [00000424e868e737] 0.014ms (+0.000ms): ata_bmdma_irq_clear+0x9/0x2b <ffffffff88032170> (ata_host_intr+0x7c/0xb6 <ffffffff88033e06>)
(T1/#136) <idle> 0 1 19 00000001 00000088 [00000424e868e88e] 0.014ms (+0.000ms): _raw_spin_lock_irq+0xb/0x2c <ffffffff802fa2dd> (__schedule+0x18c/0xad6 <ffffffff802f777f>)
(T1/#137) <...> 697 0 0 00000000 00000089 [00000424e868eb5d] 0.015ms (+0.000ms): ata_qc_complete+0x13/0x20b <ffffffff88032870> (ata_host_intr+0x9e/0xb6 <ffffffff88033e28>)
(T1/#138) <idle> 0 1 19 00000002 0000008a [00000424e868ec85] 0.015ms (+0.000ms): double_lock_balance+0xc/0x43 <ffffffff80129cf7> (__schedule+0x2f8/0xad6 <ffffffff802f78eb>)
(T1/#139) <...> 697 0 0 00000000 0000008b [00000424e868ec87] 0.015ms (+0.000ms): dma_unmap_sg+0x14/0x6d <ffffffff8011c396> (ata_qc_complete+0x132/0x20b <ffffffff8803298f>)
(T1/#140) <idle> 0 1 19 00000002 0000008c [00000424e868ed68] 0.015ms (+0.000ms): _raw_spin_trylock+0xb/0x5d <ffffffff802fa8f7> (double_lock_balance+0x1a/0x43 <ffffffff80129d05>)
(T1/#141) <...> 697 0 0 00000000 0000008d [00000424e868ed93] 0.015ms (+0.000ms): dma_unmap_single+0xc/0xe6 <ffffffff8011c2a8> (dma_unmap_sg+0x5b/0x6d <ffffffff8011c3dd>)
(T1/#142) <...> 697 0 0 00000000 0000008e [00000424e868ef1d] 0.015ms (+0.000ms): ata_scsi_qc_complete+0x10/0x89 <ffffffff88036aa1> (ata_qc_complete+0x1f2/0x20b <ffffffff88032a4f>)
(T1/#143) <...> 697 0 0 00000000 0000008f [00000424e868f076] 0.015ms (+0.000ms): scsi_done+0xc/0x24 <ffffffff880028d4> (ata_scsi_qc_complete+0x7f/0x89 <ffffffff88036b10>)
(T1/#144) <...> 697 0 0 00000000 00000090 [00000424e868f16f] 0.015ms (+0.000ms): scsi_delete_timer+0xc/0x65 <ffffffff8800576d> (scsi_done+0x14/0x24 <ffffffff880028dc>)
(T1/#145) <idle> 0 1 19 00000003 00000091 [00000424e868f1ec] 0.015ms (+0.000ms): find_next_bit+0xc/0x74 <ffffffff80200598> (__schedule+0x3a2/0xad6 <ffffffff802f7995>)
(T1/#146) <...> 697 0 0 00000000 00000092 [00000424e868f268] 0.016ms (+0.000ms): del_timer+0xe/0x5e <ffffffff8013b7a8> (scsi_delete_timer+0x1b/0x65 <ffffffff8800577c>)
(T1/#147) <...> 697 0 0 00000000 00000093 [00000424e868f359] 0.016ms (+0.000ms): lock_timer_base+0xf/0x4c <ffffffff8013b5a6> (del_timer+0x23/0x5e <ffffffff8013b7bd>)
(T1/#148) <idle> 0 1 19 00000003 00000094 [00000424e868f46a] 0.016ms (+0.000ms): find_next_bit+0xc/0x74 <ffffffff80200598> (__schedule+0x3a2/0xad6 <ffffffff802f7995>)
(T1/#149) <idle> 0 1 19 00000003 00000095 [00000424e868f589] 0.016ms (+0.000ms): __find_first_bit+0x9/0x34 <ffffffff80200551> (find_next_bit+0x65/0x74 <ffffffff802005f1>)
(T1/#150) <...> 697 0 0 00000000 00000096 [00000424e868f5fc] 0.016ms (+0.000ms): _spin_lock_irqsave+0x9/0x4b <ffffffff802f9db4> (lock_timer_base+0x27/0x4c <ffffffff8013b5be>)
(T1/#151) <...> 697 0 0 00000000 00000097 [00000424e868f735] 0.016ms (+0.000ms): account_mutex_owner_down+0x9/0x4c <ffffffff8014a3fd> (_spin_lock_irqsave+0x3a/0x4b <ffffffff802f9de5>)
(T1/#152) <idle> 0 1 19 00000003 00000098 [00000424e868f850] 0.016ms (+0.000ms): find_next_bit+0xc/0x74 <ffffffff80200598> (__schedule+0x3a2/0xad6 <ffffffff802f7995>)
(T1/#153) <...> 697 0 0 00000000 00000099 [00000424e868f8df] 0.016ms (+0.000ms): _spin_unlock_irqrestore+0xc/0x6e <ffffffff802fa13a> (del_timer+0x54/0x5e <ffffffff8013b7ee>)
(T1/#154) <idle> 0 1 19 00000003 0000009a [00000424e868f945] 0.016ms (+0.000ms): __find_first_bit+0x9/0x34 <ffffffff80200551> (find_next_bit+0x65/0x74 <ffffffff802005f1>)
(T1/#155) <...> 697 0 0 00000000 0000009b [00000424e868f9c7] 0.016ms (+0.000ms): up_mutex+0x9/0x3f <ffffffff8014b0f4> (_spin_unlock_irqrestore+0x6a/0x6e <ffffffff802fa198>)
(T1/#156) <idle> 0 1 19 00000003 0000009c [00000424e868fa58] 0.017ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__schedule+0x437/0xad6 <ffffffff802f7a2a>)
(T1/#157) <...> 697 0 0 00000000 0000009d [00000424e868fab1] 0.017ms (+0.000ms): account_mutex_owner_up+0x9/0x4b <ffffffff8014a449> (up_mutex+0x36/0x3f <ffffffff8014b121>)
(T1/#158) <idle> 0 1 19 00000002 0000009e [00000424e868fbed] 0.017ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#159) <...> 697 0 0 00000000 0000009f [00000424e868fc11] 0.017ms (+0.000ms): __scsi_done+0xc/0x9b <ffffffff88002839> (scsi_done+0x20/0x24 <ffffffff880028e8>)
(T1/#160) <idle> 0 1 19 00000002 000000a0 [00000424e868fcec] 0.017ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
(T1/#161) <...> 697 0 16 00000000 000000a1 [00000424e868fdb2] 0.017ms (+0.000ms): raise_softirq_irqoff+0x9/0x5f <ffffffff80137ad2> (__scsi_done+0x73/0x9b <ffffffff880028a0>)
(T1/#162) <idle> 0 1 19 00000002 000000a2 [00000424e868fe1b] 0.017ms (+0.000ms): dependent_sleeper+0x16/0x3f1 <ffffffff8012d508> (__schedule+0x74c/0xad6 <ffffffff802f7d3f>)
(T1/#163) <...> 697 0 16 00000000 000000a3 [00000424e868fefd] 0.017ms (+0.000ms): wakeup_softirqd+0x9/0x38 <ffffffff801373e5> (raise_softirq_irqoff+0x5d/0x5f <ffffffff80137b26>)
(T5/#164) [ => swapper ] 0.017ms (+0.000ms)
(T1/#165) <...> 697 0 16 00000000 000000a5 [00000424e8690058] 0.017ms (+0.000ms): wake_up_process+0xb/0x31 <ffffffff8012cd66> (wakeup_softirqd+0x36/0x38 <ffffffff80137412>)
(T1/#166) <idle> 0 1 17 00000002 000000a6 [00000424e8690071] 0.017ms (+0.000ms): __switch_to+0x13/0x212 <ffffffff8010c7d1> (thread_return+0x0/0x13f <ffffffff802f80c9>)
(T1/#167) <...> 697 0 16 00000000 000000a7 [00000424e8690136] 0.017ms (+0.000ms): check_preempt_wakeup+0xc/0xac <ffffffff8014a814> (wake_up_process+0x13/0x31 <ffffffff8012cd6e>)
(T3/#168) <...>-14 1D..2 17us : thread_return+0x4a/0x13f <ffffffff802f8113> <<idle>-0> (8c 62)
(T1/#169) <...> 697 0 16 00000000 000000a9 [00000424e8690245] 0.018ms (+0.000ms): try_to_wake_up+0x16/0x560 <ffffffff8012c747> (wake_up_process+0x24/0x31 <ffffffff8012cd7f>)
(T1/#170) <...> 14 1 16 00000002 000000aa [00000424e86902fc] 0.018ms (+0.000ms): _raw_spin_unlock_irq+0x9/0x44 <ffffffff802fa5d7> (thread_return+0xa3/0x13f <ffffffff802f816c>)
(T1/#171) <...> 697 0 16 00000000 000000ab [00000424e8690363] 0.018ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (try_to_wake_up+0x5d/0x560 <ffffffff8012c78e>)
(T1/#172) <...> 14 1 0 00000001 000000ac [00000424e869042d] 0.018ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irq+0x39/0x44 <ffffffff802fa607>)
(T1/#173) <...> 14 1 0 00000001 000000ad [00000424e8690556] 0.018ms (+0.000ms): trace_stop_sched_switched+0x16/0x332 <ffffffff801504d0> (thread_return+0xb1/0x13f <ffffffff802f817a>)
(T1/#174) <...> 697 0 16 00000001 000000ae [00000424e86905a9] 0.018ms (+0.000ms): idle_cpu+0x9/0x30 <ffffffff80129d37> (try_to_wake_up+0x292/0x560 <ffffffff8012c9c3>)
(T1/#175) <...> 14 1 16 00000001 000000af [00000424e869065c] 0.018ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (trace_stop_sched_switched+0x49/0x332 <ffffffff80150503>)
(T1/#176) <...> 697 0 16 00000001 000000b0 [00000424e86906b0] 0.018ms (+0.000ms): smp_send_reschedule_allbutself+0x9/0x1a <ffffffff8011809b> (try_to_wake_up+0x3e9/0x560 <ffffffff8012cb1a>)
(T1/#177) <...> 697 0 16 00000001 000000b1 [00000424e869078d] 0.018ms (+0.000ms): flat_send_IPI_allbutself+0xb/0x5b <ffffffff8011b644> (smp_send_reschedule_allbutself+0x18/0x1a <ffffffff801180aa>)
(T3/#178) <...>-14 1D..2 18us : trace_stop_sched_switched+0x6f/0x332 <ffffffff80150529> <<...>-14> (62 1)
(T1/#179) <...> 697 0 16 00000001 000000b3 [00000424e8690871] 0.018ms (+0.000ms): __bitmap_weight+0xa/0x18b <ffffffff801fbce6> (flat_send_IPI_allbutself+0x1e/0x5b <ffffffff8011b657>)
(T1/#180) <...> 14 1 16 00000003 000000b4 [00000424e8690898] 0.018ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (trace_stop_sched_switched+0xbf/0x332 <ffffffff80150579>)
(T1/#181) <...> 14 1 16 00000002 000000b5 [00000424e86909ac] 0.018ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
(T1/#182) <...> 697 0 16 00000001 000000b6 [00000424e8690a78] 0.019ms (+0.000ms): activate_task+0x10/0xe0 <ffffffff8012bc38> (try_to_wake_up+0x491/0x560 <ffffffff8012cbc2>)
(T1/#183) <...> 697 0 16 00000001 000000b7 [00000424e8690b50] 0.019ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (activate_task+0x1d/0xe0 <ffffffff8012bc45>)
(T1/#184) <...> 14 1 16 00000002 000000b8 [00000424e8690b62] 0.019ms (+9177482346838.318ms): thread_return+0xb1/0x13f <ffffffff802f817a> (thread_return+0xb1/0x13f <ffffffff802f817a>)
vim:ft=help
All this tells me is that your system's timer is screwed up (not news).
John, Ingo, any ideas?
Lee
On Fri, 2006-03-03 at 14:18 -0500, Bill Rugolsky Jr. wrote:
> On Wed, Mar 01, 2006 at 02:16:50PM -0500, Lee Revell wrote:
> > On Wed, 2006-03-01 at 19:29 +0100, Andi Kleen wrote:
> > > Sprinkle WARN_ON(in_interrupt()) all over the parts that shouldn't
> > > have interrupts
> > > off.
> >
> > Might be faster to just try the -rt kernel, it has tons of debugging
> > checks for stuff like this.
>
> After several attempts where 2.6.15-rt18 reset on startup, I whittled
> my config down to something minimal (turned off NUMA, CPUSETS, PRINTK_TIME, ...)
> and got it up and running PREEMPT_RT:
>
> rugolsky@ti94: uname -a
> Linux ti94 2.6.15-rt18-realtime #4 SMP PREEMPT Fri Mar 3 11:39:20 EST 2006 x86_64 x86_64 x86_64 GNU/Linux
>
> rugolsky@ti94: egrep 'PREEMPT|LATENCY|HZ' .config
> # CONFIG_PREEMPT_NONE is not set
> # CONFIG_PREEMPT_VOLUNTARY is not set
> # CONFIG_PREEMPT_DESKTOP is not set
> CONFIG_PREEMPT_RT=y
> CONFIG_PREEMPT=y
> CONFIG_PREEMPT_SOFTIRQS=y
> CONFIG_PREEMPT_HARDIRQS=y
> CONFIG_PREEMPT_BKL=y
> CONFIG_PREEMPT_RCU=y
> # CONFIG_HZ_100 is not set
> # CONFIG_HZ_250 is not set
> CONFIG_HZ_1000=y
> CONFIG_HZ=1000
> CONFIG_DEBUG_PREEMPT=y
> # CONFIG_WAKEUP_LATENCY_HIST is not set
> CONFIG_PREEMPT_TRACE=y
> CONFIG_CRITICAL_PREEMPT_TIMING=y
> # CONFIG_PREEMPT_OFF_HIST is not set
> CONFIG_LATENCY_TIMING=y
> CONFIG_LATENCY_TRACE=y
>
> % sudo sysctl -a | egrep 'kernel\.*(preempt|latency|trace|wakeup)'
> kernel.preempt_thresh = 0
> kernel.preempt_max_latency = 2483
> kernel.trace_all_cpus = 1
> kernel.trace_verbose = 1
> kernel.trace_print_at_crash = 1
> kernel.trace_freerunning = 0
> kernel.trace_user_trigger_irq = -1
> kernel.trace_user_trigger_irq = -1
> kernel.trace_user_triggered = 0
> kernel.trace_enabled = 1
> kernel.wakeup_timing = 1
>
> % cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> acpi_pm
>
> Should I be compiling for a different preempt mode? I've only cursorily
> followed the realtime-preempt patch discussion threads, so I am unclear as
> to what debugging facilities are available with each preemption level.
> [Is there a howto/tutorial floating around on using the debugging
> features?]
>
> I got the following trace. Since you have a great deal of experience
> interpreting these traces, perhaps you can help me interpret this one?
>
> Thanks.
>
> Bill Rugolsky
>
>
> preemption latency trace v1.1.5 on 2.6.15-rt18-realtime
> --------------------------------------------------------------------
> latency: 2483 us, #238/238, CPU#1 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
> -----------------
> | task: softirq-timer/1-14 (uid:0 nice:0 policy:1 rt_prio:1)
> -----------------
>
> (T1/#0) <...> 697 0 16 00000000 00000000 [00000424e86874c5] 0.000ms (+0.000ms): smp_apic_timer_interrupt+0xc/0x48 <ffffffff8011902a> (apic_timer_interrupt+0x84/0x8c <ffffffff8010ead0>)
> (T1/#1) <...> 697 0 20 00000000 00000001 [00000424e86876a8] 0.000ms (+0.000ms): smp_local_timer_interrupt+0xc/0x32 <ffffffff80118ad5> (smp_apic_timer_interrupt+0x3e/0x48 <ffffffff8011905c>)
> (T1/#2) <...> 697 0 20 00000000 00000002 [00000424e868778c] 0.000ms (+0.000ms): profile_tick+0xc/0x77 <ffffffff801334d4> (smp_local_timer_interrupt+0x1c/0x32 <ffffffff80118ae5>)
> (T1/#3) <...> 697 0 20 00000000 00000003 [00000424e8687885] 0.000ms (+0.000ms): profile_pc+0xc/0x71 <ffffffff8011173c> (profile_tick+0x67/0x77 <ffffffff8013352f>)
> (T1/#4) <...> 697 0 20 00000000 00000004 [00000424e86879a4] 0.000ms (+0.000ms): profile_hit+0x14/0x19f <ffffffff8013333d> (profile_tick+0x72/0x77 <ffffffff8013353a>)
> (T1/#5) <...> 697 0 20 00000000 00000005 [00000424e8687aae] 0.000ms (+0.000ms): update_process_times+0xc/0x68 <ffffffff8013b457> (smp_local_timer_interrupt+0x2e/0x32 <ffffffff80118af7>)
> (T1/#6) <...> 697 0 20 00000000 00000006 [00000424e8687baf] 0.000ms (+0.000ms): account_system_time+0x9/0x9e <ffffffff8012a19c> (update_process_times+0x3f/0x68 <ffffffff8013b48a>)
> (T1/#7) <...> 697 0 20 00000000 00000007 [00000424e8687cb0] 0.001ms (+0.000ms): acct_update_integrals+0x9/0x59 <ffffffff801571a1> (account_system_time+0x9c/0x9e <ffffffff8012a22f>)
> (T1/#8) <...> 697 0 20 00000000 00000008 [00000424e8687dca] 0.001ms (+0.000ms): run_local_timers+0x9/0x15 <ffffffff8013b0cd> (update_process_times+0x44/0x68 <ffffffff8013b48f>)
> (T1/#9) <...> 697 0 20 00000000 00000009 [00000424e8687ea7] 0.001ms (+0.000ms): raise_softirq+0xc/0x91 <ffffffff80137cf8> (run_local_timers+0x13/0x15 <ffffffff8013b0d7>)
> (T1/#10) <...> 697 0 20 00000000 0000000a [00000424e8687fce] 0.001ms (+0.000ms): wakeup_softirqd+0x9/0x38 <ffffffff801373e5> (raise_softirq+0x6f/0x91 <ffffffff80137d5b>)
> (T1/#11) <...> 697 0 20 00000000 0000000b [00000424e86880c5] 0.001ms (+0.000ms): wake_up_process+0xb/0x31 <ffffffff8012cd66> (wakeup_softirqd+0x36/0x38 <ffffffff80137412>)
> (T1/#12) <...> 697 0 20 00000000 0000000c [00000424e86881ab] 0.001ms (+0.000ms): check_preempt_wakeup+0xc/0xac <ffffffff8014a814> (wake_up_process+0x13/0x31 <ffffffff8012cd6e>)
> (T1/#13) <...> 697 0 20 00000000 0000000d [00000424e86882b4] 0.001ms (+0.000ms): try_to_wake_up+0x16/0x560 <ffffffff8012c747> (wake_up_process+0x24/0x31 <ffffffff8012cd7f>)
> (T1/#14) <...> 697 0 20 00000000 0000000e [00000424e86883ad] 0.001ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (try_to_wake_up+0x5d/0x560 <ffffffff8012c78e>)
> (T1/#15) <...> 697 0 20 00000001 0000000f [00000424e86884fd] 0.002ms (+0.000ms): idle_cpu+0x9/0x30 <ffffffff80129d37> (try_to_wake_up+0x292/0x560 <ffffffff8012c9c3>)
> (T1/#16) <idle> 0 1 23 00000003 00000010 [00000424e86885b5] 0.002ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (unmask_IO_APIC_irq+0x35/0x3a <ffffffff8011a854>)
> (T1/#17) <...> 697 0 20 00000001 00000011 [00000424e868868b] 0.002ms (+0.000ms): smp_send_reschedule_allbutself+0x9/0x1a <ffffffff8011809b> (try_to_wake_up+0x3e9/0x560 <ffffffff8012cb1a>)
> (T1/#18) <idle> 0 1 23 00000002 00000012 [00000424e86886b0] 0.002ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
> (T1/#19) <...> 697 0 20 00000001 00000013 [00000424e8688779] 0.002ms (+0.000ms): flat_send_IPI_allbutself+0xb/0x5b <ffffffff8011b644> (smp_send_reschedule_allbutself+0x18/0x1a <ffffffff801180aa>)
> (T1/#20) <idle> 0 1 23 00000002 00000014 [00000424e86887ba] 0.002ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
> (T1/#21) <...> 697 0 20 00000001 00000015 [00000424e8688855] 0.002ms (+0.000ms): __bitmap_weight+0xa/0x18b <ffffffff801fbce6> (flat_send_IPI_allbutself+0x1e/0x5b <ffffffff8011b657>)
> (T1/#22) <idle> 0 1 23 00000002 00000016 [00000424e86888ab] 0.002ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock_irqrestore+0x5e/0x62 <ffffffff802fa670>)
> (T1/#23) <idle> 0 1 23 00000002 00000017 [00000424e86889c7] 0.002ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0x12a/0x141 <ffffffff8015deb9>)
> (T1/#24) <...> 697 0 20 00000001 00000018 [00000424e8688a6c] 0.002ms (+0.000ms): activate_task+0x10/0xe0 <ffffffff8012bc38> (try_to_wake_up+0x491/0x560 <ffffffff8012cbc2>)
> (T1/#25) <idle> 0 1 23 00000001 00000019 [00000424e8688abd] 0.002ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#26) <...> 697 0 20 00000001 0000001a [00000424e8688b4b] 0.002ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (activate_task+0x1d/0xe0 <ffffffff8012bc45>)
> (T1/#27) <idle> 0 1 23 00000001 0000001b [00000424e8688bbc] 0.002ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
> (T3/#28) <...>-697 0D.h1 2us : activate_task+0x9b/0xe0 <ffffffff8012bcc3> <<...>-4> (62 1)
> (T1/#29) <idle> 0 1 23 00000001 0000001d [00000424e8688cd8] 0.003ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (do_IRQ+0x3a/0x44 <ffffffff80110767>)
> (T1/#30) <...> 697 0 20 00000001 0000001e [00000424e8688d26] 0.003ms (+0.000ms): enqueue_task+0xc/0x95 <ffffffff80129be4> (activate_task+0xa7/0xe0 <ffffffff8012bccf>)
> (T1/#31) <...> 697 0 20 00000001 0000001f [00000424e8688f26] 0.003ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (try_to_wake_up+0x54f/0x560 <ffffffff8012cc80>)
> (T1/#32) <idle> 0 1 19 00000001 00000020 [00000424e8688f9e] 0.003ms (+0.000ms): smp_reschedule_interrupt+0x9/0x16 <ffffffff801186ee> (reschedule_interrupt+0x84/0x8c <ffffffff8010e558>)
> (T1/#33) <...> 697 0 20 00000000 00000021 [00000424e868901e] 0.003ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
> (T1/#34) <...> 697 0 20 00000000 00000022 [00000424e8689137] 0.003ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
> (T1/#35) <idle> 0 1 19 00000001 00000023 [00000424e8689211] 0.003ms (+0.000ms): smp_apic_timer_interrupt+0xc/0x48 <ffffffff8011902a> (apic_timer_interrupt+0x84/0x8c <ffffffff8010ead0>)
> (T1/#36) <...> 697 0 20 00000000 00000024 [00000424e8689254] 0.003ms (+0.000ms): wake_up_process+0x2b/0x31 <ffffffff8012cd86> (wakeup_softirqd+0x36/0x38 <ffffffff80137412>)
> (T1/#37) <...> 697 0 20 00000000 00000025 [00000424e8689354] 0.003ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (raise_softirq+0x77/0x91 <ffffffff80137d63>)
> (T1/#38) <idle> 0 1 23 00000001 00000026 [00000424e8689354] 0.003ms (+0.000ms): smp_local_timer_interrupt+0xc/0x32 <ffffffff80118ad5> (smp_apic_timer_interrupt+0x3e/0x48 <ffffffff8011905c>)
> (T1/#39) <idle> 0 1 23 00000001 00000027 [00000424e8689426] 0.003ms (+0.000ms): profile_tick+0xc/0x77 <ffffffff801334d4> (smp_local_timer_interrupt+0x1c/0x32 <ffffffff80118ae5>)
> (T1/#40) <...> 697 0 20 00000000 00000028 [00000424e8689492] 0.004ms (+0.000ms): rcu_pending+0x9/0x30 <ffffffff801445e8> (update_process_times+0x4b/0x68 <ffffffff8013b496>)
> (T1/#41) <idle> 0 1 23 00000001 00000029 [00000424e8689520] 0.004ms (+0.000ms): profile_pc+0xc/0x71 <ffffffff8011173c> (profile_tick+0x67/0x77 <ffffffff8013352f>)
> (T1/#42) <...> 697 0 20 00000000 0000002a [00000424e86895c8] 0.004ms (+0.000ms): scheduler_tick+0x13/0x34c <ffffffff8012d1b9> (update_process_times+0x5e/0x68 <ffffffff8013b4a9>)
> (T1/#43) <idle> 0 1 23 00000001 0000002b [00000424e8689636] 0.004ms (+0.000ms): profile_hit+0x14/0x19f <ffffffff8013333d> (profile_tick+0x72/0x77 <ffffffff8013353a>)
> (T1/#44) <...> 697 0 20 00000000 0000002c [00000424e86896af] 0.004ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (scheduler_tick+0x3d/0x34c <ffffffff8012d1e3>)
> (T1/#45) <idle> 0 1 23 00000001 0000002d [00000424e8689754] 0.004ms (+0.000ms): update_process_times+0xc/0x68 <ffffffff8013b457> (smp_local_timer_interrupt+0x2e/0x32 <ffffffff80118af7>)
> (T1/#46) <...> 697 0 20 00000000 0000002e [00000424e86897c5] 0.004ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (scheduler_tick+0xce/0x34c <ffffffff8012d274>)
> (T1/#47) <idle> 0 1 23 00000001 0000002f [00000424e868984a] 0.004ms (+0.000ms): account_system_time+0x9/0x9e <ffffffff8012a19c> (update_process_times+0x3f/0x68 <ffffffff8013b48a>)
> (T1/#48) <...> 697 0 20 00000001 00000030 [00000424e86898f8] 0.004ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (scheduler_tick+0x330/0x34c <ffffffff8012d4d6>)
> (T1/#49) <idle> 0 1 23 00000001 00000031 [00000424e868994c] 0.004ms (+0.000ms): acct_update_integrals+0x9/0x59 <ffffffff801571a1> (account_system_time+0x9c/0x9e <ffffffff8012a22f>)
> (T1/#50) <...> 697 0 20 00000000 00000032 [00000424e8689a04] 0.004ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#51) <idle> 0 1 23 00000001 00000033 [00000424e8689a5a] 0.004ms (+0.000ms): run_local_timers+0x9/0x15 <ffffffff8013b0cd> (update_process_times+0x44/0x68 <ffffffff8013b48f>)
> (T1/#52) <...> 697 0 20 00000000 00000034 [00000424e8689b0b] 0.004ms (+0.000ms): rebalance_tick+0x16/0x2e8 <ffffffff8012ced4> (scheduler_tick+0x340/0x34c <ffffffff8012d4e6>)
> (T1/#53) <idle> 0 1 23 00000001 00000035 [00000424e8689b36] 0.004ms (+0.000ms): raise_softirq+0xc/0x91 <ffffffff80137cf8> (run_local_timers+0x13/0x15 <ffffffff8013b0d7>)
> (T1/#54) <idle> 0 1 23 00000001 00000036 [00000424e8689c41] 0.005ms (+0.000ms): wakeup_softirqd+0x9/0x38 <ffffffff801373e5> (raise_softirq+0x6f/0x91 <ffffffff80137d5b>)
> (T1/#55) <idle> 0 1 23 00000001 00000037 [00000424e8689d50] 0.005ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (raise_softirq+0x77/0x91 <ffffffff80137d63>)
> (T1/#56) <...> 697 0 20 00000000 00000038 [00000424e8689dc9] 0.005ms (+0.000ms): softlockup_tick+0xf/0x11d <ffffffff8015d672> (update_process_times+0x63/0x68 <ffffffff8013b4ae>)
> (T1/#57) <idle> 0 1 23 00000001 00000039 [00000424e8689e81] 0.005ms (+0.000ms): rcu_pending+0x9/0x30 <ffffffff801445e8> (update_process_times+0x4b/0x68 <ffffffff8013b496>)
> (T1/#58) <...> 697 0 20 00000000 0000003a [00000424e8689ef2] 0.005ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (smp_apic_timer_interrupt+0x43/0x48 <ffffffff80119061>)
> (T1/#59) <idle> 0 1 23 00000001 0000003b [00000424e8689f91] 0.005ms (+0.000ms): scheduler_tick+0x13/0x34c <ffffffff8012d1b9> (update_process_times+0x5e/0x68 <ffffffff8013b4a9>)
> (T1/#60) <idle> 0 1 23 00000001 0000003c [00000424e868a078] 0.005ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (scheduler_tick+0x3d/0x34c <ffffffff8012d1e3>)
> (T1/#61) <idle> 0 1 23 00000001 0000003d [00000424e868a17d] 0.005ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (scheduler_tick+0x81/0x34c <ffffffff8012d227>)
> (T1/#62) <...> 697 0 16 00000000 0000003e [00000424e868a1e5] 0.005ms (+0.000ms): do_IRQ+0xc/0x44 <ffffffff80110739> (ret_from_intr+0x0/0x12 <ffffffff8010e276>)
> (T1/#63) <idle> 0 1 23 00000002 0000003f [00000424e868a2cf] 0.005ms (+0.000ms): resched_task+0xc/0x79 <ffffffff8012a958> (scheduler_tick+0x95/0x34c <ffffffff8012d23b>)
> (T1/#64) <...> 697 0 20 00000000 00000040 [00000424e868a332] 0.005ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (__do_IRQ+0x5d/0x141 <ffffffff8015ddec>)
> (T1/#65) <idle> 0 1 23 00000002 00000041 [00000424e868a3e6] 0.006ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (scheduler_tick+0x9d/0x34c <ffffffff8012d243>)
> (T1/#66) <...> 697 0 20 00000001 00000042 [00000424e868a469] 0.006ms (+0.000ms): mask_and_ack_level_ioapic_irq+0x10/0xa2 <ffffffff8011aa2d> (__do_IRQ+0x72/0x141 <ffffffff8015de01>)
> (T1/#67) <idle> 0 1 23 00000001 00000043 [00000424e868a4e0] 0.006ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#68) <...> 697 0 20 00000001 00000044 [00000424e868a548] 0.006ms (+0.000ms): mask_IO_APIC_irq+0xb/0x11e <ffffffff8011a90a> (mask_and_ack_level_ioapic_irq+0x8e/0xa2 <ffffffff8011aaab>)
> (T1/#69) <idle> 0 1 23 00000001 00000045 [00000424e868a5e8] 0.006ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
> (T1/#70) <...> 697 0 20 00000001 00000046 [00000424e868a6bd] 0.006ms (+0.000ms): _raw_spin_lock_irqsave+0xc/0x33 <ffffffff802fa2ab> (mask_IO_APIC_irq+0x19/0x11e <ffffffff8011a918>)
> (T1/#71) <idle> 0 1 23 00000001 00000047 [00000424e868a70c] 0.006ms (+0.000ms): rebalance_tick+0x16/0x2e8 <ffffffff8012ced4> (scheduler_tick+0x340/0x34c <ffffffff8012d4e6>)
> (T1/#72) <idle> 0 1 23 00000001 00000048 [00000424e868a936] 0.006ms (+0.000ms): softlockup_tick+0xf/0x11d <ffffffff8015d672> (update_process_times+0x63/0x68 <ffffffff8013b4ae>)
> (T1/#73) <idle> 0 1 23 00000001 00000049 [00000424e868aa5e] 0.006ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (smp_apic_timer_interrupt+0x43/0x48 <ffffffff80119061>)
> (T1/#74) <idle> 0 1 19 00000001 0000004a [00000424e868ad2f] 0.007ms (+0.000ms): do_IRQ+0xc/0x44 <ffffffff80110739> (ret_from_intr+0x0/0x12 <ffffffff8010e276>)
> (T1/#75) <idle> 0 1 23 00000001 0000004b [00000424e868ae68] 0.007ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (__do_IRQ+0x5d/0x141 <ffffffff8015ddec>)
> (T1/#76) <idle> 0 1 23 00000002 0000004c [00000424e868b067] 0.007ms (+0.000ms): ack_edge_ioapic_irq+0x10/0xba <ffffffff8011ab21> (__do_IRQ+0x72/0x141 <ffffffff8015de01>)
> (T1/#77) <idle> 0 1 23 00000002 0000004d [00000424e868b16b] 0.007ms (+0.000ms): redirect_hardirq+0x9/0x53 <ffffffff8015d909> (__do_IRQ+0xb5/0x141 <ffffffff8015de44>)
> (T1/#78) <idle> 0 1 23 00000002 0000004e [00000424e868b283] 0.007ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0xc1/0x141 <ffffffff8015de50>)
> (T1/#79) <idle> 0 1 23 00000001 0000004f [00000424e868b38d] 0.007ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#80) <idle> 0 1 23 00000001 00000050 [00000424e868b4a0] 0.008ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
> (T1/#81) <idle> 0 1 23 00000001 00000051 [00000424e868b5af] 0.008ms (+0.000ms): handle_IRQ_event+0x16/0x114 <ffffffff8015d96f> (__do_IRQ+0xd1/0x141 <ffffffff8015de60>)
> (T1/#82) <idle> 0 1 23 00000001 00000052 [00000424e868b699] 0.008ms (+0.000ms): timer_interrupt+0xb/0x62 <ffffffff801117ac> (handle_IRQ_event+0x6a/0x114 <ffffffff8015d9c3>)
> (T1/#83) <idle> 0 1 23 00000001 00000053 [00000424e868b789] 0.008ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (timer_interrupt+0x1a/0x62 <ffffffff801117bb>)
> (T1/#84) <idle> 0 1 23 00000002 00000054 [00000424e868b8c5] 0.008ms (+0.000ms): do_timer+0x9/0x12 <ffffffff8013b0e2> (timer_interrupt+0x28/0x62 <ffffffff801117c9>)
> (T1/#85) <idle> 0 1 23 00000002 00000055 [00000424e868ba17] 0.008ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (timer_interrupt+0x4b/0x62 <ffffffff801117ec>)
> (T1/#86) <...> 697 0 20 00000002 00000056 [00000424e868ba4b] 0.008ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (mask_IO_APIC_irq+0x11a/0x11e <ffffffff8011aa19>)
> (T1/#87) <idle> 0 1 23 00000001 00000057 [00000424e868bb18] 0.008ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#88) <...> 697 0 20 00000001 00000058 [00000424e868bb4d] 0.008ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
> (T1/#89) <idle> 0 1 23 00000001 00000059 [00000424e868bc15] 0.009ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
> (T1/#90) <...> 697 0 20 00000001 0000005a [00000424e868bc62] 0.009ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
> (T1/#91) <idle> 0 1 23 00000001 0000005b [00000424e868bd30] 0.009ms (+0.000ms): smp_send_timer_broadcast_ipi+0x9/0x31 <ffffffff80118a91> (timer_interrupt+0x59/0x62 <ffffffff801117fa>)
> (T1/#92) <...> 697 0 20 00000001 0000005c [00000424e868bd98] 0.009ms (+0.000ms): redirect_hardirq+0x9/0x53 <ffffffff8015d909> (__do_IRQ+0xb5/0x141 <ffffffff8015de44>)
> (T1/#93) <idle> 0 1 23 00000001 0000005d [00000424e868be66] 0.009ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (__do_IRQ+0xdb/0x141 <ffffffff8015de6a>)
> (T1/#94) <...> 697 0 20 00000001 0000005e [00000424e868bed0] 0.009ms (+0.000ms): wake_up_process+0xb/0x31 <ffffffff8012cd66> (redirect_hardirq+0x46/0x53 <ffffffff8015d946>)
> (T1/#95) <idle> 0 1 23 00000002 0000005f [00000424e868bfa8] 0.009ms (+0.000ms): note_interrupt+0x16/0x227 <ffffffff8015ec77> (__do_IRQ+0xf5/0x141 <ffffffff8015de84>)
> (T1/#96) <...> 697 0 20 00000001 00000060 [00000424e868bfe2] 0.009ms (+0.000ms): check_preempt_wakeup+0xc/0xac <ffffffff8014a814> (wake_up_process+0x13/0x31 <ffffffff8012cd6e>)
> (T1/#97) <idle> 0 1 23 00000002 00000061 [00000424e868c0a8] 0.009ms (+0.000ms): unmask_IO_APIC_irq+0xc/0x3a <ffffffff8011a82b> (__do_IRQ+0x122/0x141 <ffffffff8015deb1>)
> (T1/#98) <...> 697 0 20 00000001 00000062 [00000424e868c0d6] 0.009ms (+0.000ms): try_to_wake_up+0x16/0x560 <ffffffff8012c747> (wake_up_process+0x24/0x31 <ffffffff8012cd7f>)
> (T1/#99) <idle> 0 1 23 00000002 00000063 [00000424e868c19a] 0.009ms (+0.000ms): _raw_spin_lock_irqsave+0xc/0x33 <ffffffff802fa2ab> (unmask_IO_APIC_irq+0x1b/0x3a <ffffffff8011a83a>)
> (T1/#100) <...> 697 0 20 00000001 00000064 [00000424e868c1f8] 0.009ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (try_to_wake_up+0x5d/0x560 <ffffffff8012c78e>)
> (T1/#101) <...> 697 0 20 00000002 00000065 [00000424e868c3d9] 0.010ms (+0.000ms): idle_cpu+0x9/0x30 <ffffffff80129d37> (try_to_wake_up+0x292/0x560 <ffffffff8012c9c3>)
> (T1/#102) <idle> 0 1 23 00000003 00000066 [00000424e868c439] 0.010ms (+0.000ms): __unmask_IO_APIC_irq+0x9/0xff <ffffffff8011a729> (unmask_IO_APIC_irq+0x26/0x3a <ffffffff8011a845>)
> (T1/#103) <...> 697 0 20 00000002 00000067 [00000424e868c538] 0.010ms (+0.000ms): smp_send_reschedule_allbutself+0x9/0x1a <ffffffff8011809b> (try_to_wake_up+0x3e9/0x560 <ffffffff8012cb1a>)
> (T1/#104) <...> 697 0 20 00000002 00000068 [00000424e868c674] 0.010ms (+0.000ms): flat_send_IPI_allbutself+0xb/0x5b <ffffffff8011b644> (smp_send_reschedule_allbutself+0x18/0x1a <ffffffff801180aa>)
> (T1/#105) <...> 697 0 20 00000002 00000069 [00000424e868c74e] 0.010ms (+0.000ms): __bitmap_weight+0xa/0x18b <ffffffff801fbce6> (flat_send_IPI_allbutself+0x1e/0x5b <ffffffff8011b657>)
> (T1/#106) <...> 697 0 20 00000002 0000006a [00000424e868c95a] 0.010ms (+0.000ms): activate_task+0x10/0xe0 <ffffffff8012bc38> (try_to_wake_up+0x491/0x560 <ffffffff8012cbc2>)
> (T1/#107) <...> 697 0 20 00000002 0000006b [00000424e868ca36] 0.010ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (activate_task+0x1d/0xe0 <ffffffff8012bc45>)
> (T3/#108) <...>-697 0D.h2 11us : activate_task+0x9b/0xe0 <ffffffff8012bcc3> <<...>-1432> (3a 2)
> (T1/#109) <...> 697 0 20 00000002 0000006d [00000424e868cc15] 0.011ms (+0.000ms): enqueue_task+0xc/0x95 <ffffffff80129be4> (activate_task+0xa7/0xe0 <ffffffff8012bccf>)
> (T1/#110) <...> 697 0 20 00000002 0000006e [00000424e868cdf1] 0.011ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (try_to_wake_up+0x54f/0x560 <ffffffff8012cc80>)
> (T1/#111) <...> 697 0 20 00000001 0000006f [00000424e868cf1a] 0.011ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
> (T1/#112) <...> 697 0 20 00000001 00000070 [00000424e868d02f] 0.011ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
> (T1/#113) <...> 697 0 20 00000001 00000071 [00000424e868d147] 0.011ms (+0.000ms): wake_up_process+0x2b/0x31 <ffffffff8012cd86> (redirect_hardirq+0x46/0x53 <ffffffff8015d946>)
> (T1/#114) <...> 697 0 20 00000001 00000072 [00000424e868d261] 0.011ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0x12a/0x141 <ffffffff8015deb9>)
> (T1/#115) <...> 697 0 20 00000000 00000073 [00000424e868d356] 0.012ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#116) <...> 697 0 20 00000000 00000074 [00000424e868d470] 0.012ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (do_IRQ+0x3a/0x44 <ffffffff80110767>)
> (T1/#117) <...> 697 0 0 00000000 00000075 [00000424e868d72e] 0.012ms (+0.000ms): ata_host_intr+0xf/0xb6 <ffffffff88033d99> (nv_interrupt+0x65/0xa6 <ffffffff88042065>)
> (T1/#118) <...> 697 0 0 00000000 00000076 [00000424e868d81d] 0.012ms (+0.000ms): ata_bmdma_status+0x9/0x27 <ffffffff88031e66> (ata_host_intr+0x3e/0xb6 <ffffffff88033dc8>)
> (T1/#119) <idle> 0 1 23 00000003 00000077 [00000424e868d846] 0.012ms (+0.000ms): _raw_spin_unlock_irqrestore+0xb/0x62 <ffffffff802fa61d> (unmask_IO_APIC_irq+0x35/0x3a <ffffffff8011a854>)
> (T1/#120) <idle> 0 1 23 00000002 00000078 [00000424e868d958] 0.012ms (+0.000ms): check_raw_flags+0x9/0x5b <ffffffff8014a6f5> (_raw_spin_unlock_irqrestore+0x26/0x62 <ffffffff802fa638>)
> (T1/#121) <idle> 0 1 23 00000002 00000079 [00000424e868da62] 0.012ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irqrestore+0x55/0x62 <ffffffff802fa667>)
> (T1/#122) <...> 697 0 0 00000000 0000007a [00000424e868dacb] 0.012ms (+0.000ms): ata_bmdma_stop+0x9/0x32 <ffffffff88031e34> (ata_host_intr+0x52/0xb6 <ffffffff88033ddc>)
> (T1/#123) <idle> 0 1 23 00000002 0000007b [00000424e868db53] 0.013ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock_irqrestore+0x5e/0x62 <ffffffff802fa670>)
> (T1/#124) <idle> 0 1 23 00000002 0000007c [00000424e868dc6f] 0.013ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__do_IRQ+0x12a/0x141 <ffffffff8015deb9>)
> (T1/#125) <idle> 0 1 23 00000001 0000007d [00000424e868dd65] 0.013ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#126) <idle> 0 1 23 00000001 0000007e [00000424e868de78] 0.013ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
> (T1/#127) <...> 697 0 0 00000000 0000007f [00000424e868dec3] 0.013ms (+0.000ms): ata_altstatus+0x9/0x34 <ffffffff88031e00> (ata_bmdma_stop+0x30/0x32 <ffffffff88031e5b>)
> (T1/#128) <idle> 0 1 23 00000001 00000080 [00000424e868df94] 0.013ms (+0.000ms): irq_exit+0x9/0x28 <ffffffff80137aaa> (do_IRQ+0x3a/0x44 <ffffffff80110767>)
> (T1/#129) <...> 697 0 0 00000000 00000081 [00000424e868e150] 0.013ms (+0.000ms): ata_altstatus+0x9/0x34 <ffffffff88031e00> (ata_host_intr+0x5a/0xb6 <ffffffff88033de4>)
> (T1/#130) <idle> 0 1 19 00000001 00000082 [00000424e868e25a] 0.013ms (+0.000ms): smp_reschedule_interrupt+0x9/0x16 <ffffffff801186ee> (reschedule_interrupt+0x84/0x8c <ffffffff8010e558>)
> (T1/#131) <...> 697 0 0 00000000 00000083 [00000424e868e3d5] 0.014ms (+0.000ms): ata_check_status+0x9/0x23 <ffffffff88031ddd> (ata_host_intr+0x68/0xb6 <ffffffff88033df2>)
> (T1/#132) <idle> 0 1 19 00000000 00000084 [00000424e868e465] 0.014ms (+0.000ms): __schedule+0x16/0xad6 <ffffffff802f7609> (cpu_idle+0xbe/0xd3 <ffffffff8010c6dd>)
> (T1/#133) <idle> 0 1 19 00000000 00000085 [00000424e868e560] 0.014ms (+0.000ms): profile_hit+0x14/0x19f <ffffffff8013333d> (__schedule+0xb0/0xad6 <ffffffff802f76a3>)
> (T1/#134) <idle> 0 1 19 00000001 00000086 [00000424e868e6a4] 0.014ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (__schedule+0x110/0xad6 <ffffffff802f7703>)
> (T1/#135) <...> 697 0 0 00000000 00000087 [00000424e868e737] 0.014ms (+0.000ms): ata_bmdma_irq_clear+0x9/0x2b <ffffffff88032170> (ata_host_intr+0x7c/0xb6 <ffffffff88033e06>)
> (T1/#136) <idle> 0 1 19 00000001 00000088 [00000424e868e88e] 0.014ms (+0.000ms): _raw_spin_lock_irq+0xb/0x2c <ffffffff802fa2dd> (__schedule+0x18c/0xad6 <ffffffff802f777f>)
> (T1/#137) <...> 697 0 0 00000000 00000089 [00000424e868eb5d] 0.015ms (+0.000ms): ata_qc_complete+0x13/0x20b <ffffffff88032870> (ata_host_intr+0x9e/0xb6 <ffffffff88033e28>)
> (T1/#138) <idle> 0 1 19 00000002 0000008a [00000424e868ec85] 0.015ms (+0.000ms): double_lock_balance+0xc/0x43 <ffffffff80129cf7> (__schedule+0x2f8/0xad6 <ffffffff802f78eb>)
> (T1/#139) <...> 697 0 0 00000000 0000008b [00000424e868ec87] 0.015ms (+0.000ms): dma_unmap_sg+0x14/0x6d <ffffffff8011c396> (ata_qc_complete+0x132/0x20b <ffffffff8803298f>)
> (T1/#140) <idle> 0 1 19 00000002 0000008c [00000424e868ed68] 0.015ms (+0.000ms): _raw_spin_trylock+0xb/0x5d <ffffffff802fa8f7> (double_lock_balance+0x1a/0x43 <ffffffff80129d05>)
> (T1/#141) <...> 697 0 0 00000000 0000008d [00000424e868ed93] 0.015ms (+0.000ms): dma_unmap_single+0xc/0xe6 <ffffffff8011c2a8> (dma_unmap_sg+0x5b/0x6d <ffffffff8011c3dd>)
> (T1/#142) <...> 697 0 0 00000000 0000008e [00000424e868ef1d] 0.015ms (+0.000ms): ata_scsi_qc_complete+0x10/0x89 <ffffffff88036aa1> (ata_qc_complete+0x1f2/0x20b <ffffffff88032a4f>)
> (T1/#143) <...> 697 0 0 00000000 0000008f [00000424e868f076] 0.015ms (+0.000ms): scsi_done+0xc/0x24 <ffffffff880028d4> (ata_scsi_qc_complete+0x7f/0x89 <ffffffff88036b10>)
> (T1/#144) <...> 697 0 0 00000000 00000090 [00000424e868f16f] 0.015ms (+0.000ms): scsi_delete_timer+0xc/0x65 <ffffffff8800576d> (scsi_done+0x14/0x24 <ffffffff880028dc>)
> (T1/#145) <idle> 0 1 19 00000003 00000091 [00000424e868f1ec] 0.015ms (+0.000ms): find_next_bit+0xc/0x74 <ffffffff80200598> (__schedule+0x3a2/0xad6 <ffffffff802f7995>)
> (T1/#146) <...> 697 0 0 00000000 00000092 [00000424e868f268] 0.016ms (+0.000ms): del_timer+0xe/0x5e <ffffffff8013b7a8> (scsi_delete_timer+0x1b/0x65 <ffffffff8800577c>)
> (T1/#147) <...> 697 0 0 00000000 00000093 [00000424e868f359] 0.016ms (+0.000ms): lock_timer_base+0xf/0x4c <ffffffff8013b5a6> (del_timer+0x23/0x5e <ffffffff8013b7bd>)
> (T1/#148) <idle> 0 1 19 00000003 00000094 [00000424e868f46a] 0.016ms (+0.000ms): find_next_bit+0xc/0x74 <ffffffff80200598> (__schedule+0x3a2/0xad6 <ffffffff802f7995>)
> (T1/#149) <idle> 0 1 19 00000003 00000095 [00000424e868f589] 0.016ms (+0.000ms): __find_first_bit+0x9/0x34 <ffffffff80200551> (find_next_bit+0x65/0x74 <ffffffff802005f1>)
> (T1/#150) <...> 697 0 0 00000000 00000096 [00000424e868f5fc] 0.016ms (+0.000ms): _spin_lock_irqsave+0x9/0x4b <ffffffff802f9db4> (lock_timer_base+0x27/0x4c <ffffffff8013b5be>)
> (T1/#151) <...> 697 0 0 00000000 00000097 [00000424e868f735] 0.016ms (+0.000ms): account_mutex_owner_down+0x9/0x4c <ffffffff8014a3fd> (_spin_lock_irqsave+0x3a/0x4b <ffffffff802f9de5>)
> (T1/#152) <idle> 0 1 19 00000003 00000098 [00000424e868f850] 0.016ms (+0.000ms): find_next_bit+0xc/0x74 <ffffffff80200598> (__schedule+0x3a2/0xad6 <ffffffff802f7995>)
> (T1/#153) <...> 697 0 0 00000000 00000099 [00000424e868f8df] 0.016ms (+0.000ms): _spin_unlock_irqrestore+0xc/0x6e <ffffffff802fa13a> (del_timer+0x54/0x5e <ffffffff8013b7ee>)
> (T1/#154) <idle> 0 1 19 00000003 0000009a [00000424e868f945] 0.016ms (+0.000ms): __find_first_bit+0x9/0x34 <ffffffff80200551> (find_next_bit+0x65/0x74 <ffffffff802005f1>)
> (T1/#155) <...> 697 0 0 00000000 0000009b [00000424e868f9c7] 0.016ms (+0.000ms): up_mutex+0x9/0x3f <ffffffff8014b0f4> (_spin_unlock_irqrestore+0x6a/0x6e <ffffffff802fa198>)
> (T1/#156) <idle> 0 1 19 00000003 0000009c [00000424e868fa58] 0.017ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (__schedule+0x437/0xad6 <ffffffff802f7a2a>)
> (T1/#157) <...> 697 0 0 00000000 0000009d [00000424e868fab1] 0.017ms (+0.000ms): account_mutex_owner_up+0x9/0x4b <ffffffff8014a449> (up_mutex+0x36/0x3f <ffffffff8014b121>)
> (T1/#158) <idle> 0 1 19 00000002 0000009e [00000424e868fbed] 0.017ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#159) <...> 697 0 0 00000000 0000009f [00000424e868fc11] 0.017ms (+0.000ms): __scsi_done+0xc/0x9b <ffffffff88002839> (scsi_done+0x20/0x24 <ffffffff880028e8>)
> (T1/#160) <idle> 0 1 19 00000002 000000a0 [00000424e868fcec] 0.017ms (+0.000ms): preempt_schedule+0xc/0x9d <ffffffff802f82a1> (_raw_spin_unlock+0x3c/0x3e <ffffffff802fa72a>)
> (T1/#161) <...> 697 0 16 00000000 000000a1 [00000424e868fdb2] 0.017ms (+0.000ms): raise_softirq_irqoff+0x9/0x5f <ffffffff80137ad2> (__scsi_done+0x73/0x9b <ffffffff880028a0>)
> (T1/#162) <idle> 0 1 19 00000002 000000a2 [00000424e868fe1b] 0.017ms (+0.000ms): dependent_sleeper+0x16/0x3f1 <ffffffff8012d508> (__schedule+0x74c/0xad6 <ffffffff802f7d3f>)
> (T1/#163) <...> 697 0 16 00000000 000000a3 [00000424e868fefd] 0.017ms (+0.000ms): wakeup_softirqd+0x9/0x38 <ffffffff801373e5> (raise_softirq_irqoff+0x5d/0x5f <ffffffff80137b26>)
> (T5/#164) [ => swapper ] 0.017ms (+0.000ms)
> (T1/#165) <...> 697 0 16 00000000 000000a5 [00000424e8690058] 0.017ms (+0.000ms): wake_up_process+0xb/0x31 <ffffffff8012cd66> (wakeup_softirqd+0x36/0x38 <ffffffff80137412>)
> (T1/#166) <idle> 0 1 17 00000002 000000a6 [00000424e8690071] 0.017ms (+0.000ms): __switch_to+0x13/0x212 <ffffffff8010c7d1> (thread_return+0x0/0x13f <ffffffff802f80c9>)
> (T1/#167) <...> 697 0 16 00000000 000000a7 [00000424e8690136] 0.017ms (+0.000ms): check_preempt_wakeup+0xc/0xac <ffffffff8014a814> (wake_up_process+0x13/0x31 <ffffffff8012cd6e>)
> (T3/#168) <...>-14 1D..2 17us : thread_return+0x4a/0x13f <ffffffff802f8113> <<idle>-0> (8c 62)
> (T1/#169) <...> 697 0 16 00000000 000000a9 [00000424e8690245] 0.018ms (+0.000ms): try_to_wake_up+0x16/0x560 <ffffffff8012c747> (wake_up_process+0x24/0x31 <ffffffff8012cd7f>)
> (T1/#170) <...> 14 1 16 00000002 000000aa [00000424e86902fc] 0.018ms (+0.000ms): _raw_spin_unlock_irq+0x9/0x44 <ffffffff802fa5d7> (thread_return+0xa3/0x13f <ffffffff802f816c>)
> (T1/#171) <...> 697 0 16 00000000 000000ab [00000424e8690363] 0.018ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (try_to_wake_up+0x5d/0x560 <ffffffff8012c78e>)
> (T1/#172) <...> 14 1 0 00000001 000000ac [00000424e869042d] 0.018ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock_irq+0x39/0x44 <ffffffff802fa607>)
> (T1/#173) <...> 14 1 0 00000001 000000ad [00000424e8690556] 0.018ms (+0.000ms): trace_stop_sched_switched+0x16/0x332 <ffffffff801504d0> (thread_return+0xb1/0x13f <ffffffff802f817a>)
> (T1/#174) <...> 697 0 16 00000001 000000ae [00000424e86905a9] 0.018ms (+0.000ms): idle_cpu+0x9/0x30 <ffffffff80129d37> (try_to_wake_up+0x292/0x560 <ffffffff8012c9c3>)
> (T1/#175) <...> 14 1 16 00000001 000000af [00000424e869065c] 0.018ms (+0.000ms): _raw_spin_lock+0xb/0x25 <ffffffff802fa1a7> (trace_stop_sched_switched+0x49/0x332 <ffffffff80150503>)
> (T1/#176) <...> 697 0 16 00000001 000000b0 [00000424e86906b0] 0.018ms (+0.000ms): smp_send_reschedule_allbutself+0x9/0x1a <ffffffff8011809b> (try_to_wake_up+0x3e9/0x560 <ffffffff8012cb1a>)
> (T1/#177) <...> 697 0 16 00000001 000000b1 [00000424e869078d] 0.018ms (+0.000ms): flat_send_IPI_allbutself+0xb/0x5b <ffffffff8011b644> (smp_send_reschedule_allbutself+0x18/0x1a <ffffffff801180aa>)
> (T3/#178) <...>-14 1D..2 18us : trace_stop_sched_switched+0x6f/0x332 <ffffffff80150529> <<...>-14> (62 1)
> (T1/#179) <...> 697 0 16 00000001 000000b3 [00000424e8690871] 0.018ms (+0.000ms): __bitmap_weight+0xa/0x18b <ffffffff801fbce6> (flat_send_IPI_allbutself+0x1e/0x5b <ffffffff8011b657>)
> (T1/#180) <...> 14 1 16 00000003 000000b4 [00000424e8690898] 0.018ms (+0.000ms): _raw_spin_unlock+0x9/0x3e <ffffffff802fa6f7> (trace_stop_sched_switched+0xbf/0x332 <ffffffff80150579>)
> (T1/#181) <...> 14 1 16 00000002 000000b5 [00000424e86909ac] 0.018ms (+0.000ms): constant_test_bit+0x9/0x25 <ffffffff80152845> (_raw_spin_unlock+0x33/0x3e <ffffffff802fa721>)
> (T1/#182) <...> 697 0 16 00000001 000000b6 [00000424e8690a78] 0.019ms (+0.000ms): activate_task+0x10/0xe0 <ffffffff8012bc38> (try_to_wake_up+0x491/0x560 <ffffffff8012cbc2>)
> (T1/#183) <...> 697 0 16 00000001 000000b7 [00000424e8690b50] 0.019ms (+0.000ms): sched_clock+0x9/0x26 <ffffffff8011180c> (activate_task+0x1d/0xe0 <ffffffff8012bc45>)
> (T1/#184) <...> 14 1 16 00000002 000000b8 [00000424e8690b62] 0.019ms (+9177482346838.318ms): thread_return+0xb1/0x13f <ffffffff802f817a> (thread_return+0xb1/0x13f <ffffffff802f817a>)
>
>
> vim:ft=help
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
Lee Revell wrote:
> All this tells me is that your system's timer is screwed up (not news).
Or sata_nv/libata is to blame.
Jeff
On Fri, Mar 03, 2006 at 05:09:57PM -0500, Jeff Garzik wrote:
> Or sata_nv/libata is to blame.
In case you are coming late to the thread:
The lost ticks are closely correlated with sata_nv disk activity on
multiple disks, and the problem is easily reproducable with "find /usr |
cpio -o >/dev/null" on an MD RAID1 -- but not on a single disk.
Andi suggested:
Yes, I bet something forgets to turn on interrupts again and it's
picked up by (and blamed on) the next guy who does an unconditional
sti, which happens to be __do_sofitrq or idle.
That sounds right to me.
I built 2.6.16-rc5-git6 yesterday, and it still suffers from the same
issue.
-Bill
Bill Rugolsky Jr. wrote:
> On Fri, Mar 03, 2006 at 05:09:57PM -0500, Jeff Garzik wrote:
>
>>Or sata_nv/libata is to blame.
>
>
> In case you are coming late to the thread:
I'm not. Thus my comments refuting Lee's silly speculation.
> Andi suggested:
>
> Yes, I bet something forgets to turn on interrupts again and it's
> picked up by (and blamed on) the next guy who does an unconditional
> sti, which happens to be __do_sofitrq or idle.
>
> That sounds right to me.
Unlikely. More likely is a disabled interrupt period is longer than a
tick period, or similar.
Jeff
On Fri, 2006-03-03 at 18:46 -0500, Jeff Garzik wrote:
> > In case you are coming late to the thread:
>
> I'm not. Thus my comments refuting Lee's silly speculation.
>
I did not engage in any speculation at all, I only said the timing in
that latency trace was screwed up which is obvious.
Lee
On Saturday 04 March 2006 00:43, Bill Rugolsky Jr. wrote:
> I built 2.6.16-rc5-git6 yesterday, and it still suffers from the same
> issue.
FWIW i looked over sata_nv and libata-{core,scsi} and I couldn't find
any obviously unmatched irqsave/irqrestore. So it would need instrumentation.
In theory it could be also hardware i suppose.
-Andi
On Saturday 04 March 2006 00:46, Jeff Garzik wrote:
> More likely is a disabled interrupt period is longer than a
> tick period, or similar.
Then the ticks wouldn't be attributed to idle and softirq.
They are both special in that they do an unconditional local_irq_enable()
instead of the usual save/restore.
-Andi
On Fri, 2006-03-03 at 18:43 -0500, Bill Rugolsky Jr. wrote:
> On Fri, Mar 03, 2006 at 05:09:57PM -0500, Jeff Garzik wrote:
> > Or sata_nv/libata is to blame.
>
> In case you are coming late to the thread:
>
> The lost ticks are closely correlated with sata_nv disk activity on
> multiple disks, and the problem is easily reproducable with "find /usr |
> cpio -o >/dev/null" on an MD RAID1 -- but not on a single disk.
>
> Andi suggested:
>
> Yes, I bet something forgets to turn on interrupts again and it's
> picked up by (and blamed on) the next guy who does an unconditional
> sti, which happens to be __do_sofitrq or idle.
>
> That sounds right to me.
>
> I built 2.6.16-rc5-git6 yesterday, and it still suffers from the same
> issue.
>
Not sure this will help in anyway, but anyhow.
I have had this system for about 6-8 months (maybe 10) now. It was
originally a Asus A8N-SLI Deluxe with a 3200+ Athlon64. In November I
changed to a Asus A8N-SLI Premium, and added another 1GB memory (now
have 2GB memory). In all that time I have not had any issues with lost
ticks, but I was hesitant to get a X2 processor due to the issue that
some people had.
Beginning February I got an Athlon64 X2 3800+ processor, and since that
time I have also had no issues with lost ticks. I usually run latest
git kernel +/- a week. No extra patches, except I started using Alan's
libata PATA stuff a week or so back as well.
Only difference I can see that might be of consequence, is:
1) Board type? Not sure if anybody with an A8N-SLI had any lost tick
issues ?
2) I do not use MD RAID1, but have 2 ST380013AS striped with
device-mapper's stripe module.
3) If I remember correctly, then I have the 2 hdd's on nv_sata ports 3
and 4, with ports 1 and 2 disabled, else they show up as sdc and sdd.
Not sure if its an A8N-SLI only peculiarity, and not 100% sure of the
port order - I can check if it might be an issue?
4) I do not use the NV lan adapter, as I had issues back when I got the
system, but rather the extra Marvell controller (skge module). I think
it picked up fine, etc, but it lost connection after a minute or two.
5) I run the processor at 240FSB (or HT or whatever) with the memory at
333 (166 on some boards) multiplier (ending up at running 200Mhz
anyhow). Not sure if this might make any difference, but just listing
it in case.
6) Haven't checked if this makes any difference, but the board have an
option for ACPI 2.0 support, which I have enabled.
If anything might be of relevance, or you want me to try something, just
say it. Same with extra info that might be needed.
Regards,
--
Martin Schlemmer
On Sat, Mar 04, 2006 at 02:06:45PM +0200, Martin Schlemmer wrote:
> On Fri, 2006-03-03 at 18:43 -0500, Bill Rugolsky Jr. wrote:
> > On Fri, Mar 03, 2006 at 05:09:57PM -0500, Jeff Garzik wrote:
> > > Or sata_nv/libata is to blame.
> >
> > In case you are coming late to the thread:
> >
> > The lost ticks are closely correlated with sata_nv disk activity on
> > multiple disks, and the problem is easily reproducable with "find /usr |
> > cpio -o >/dev/null" on an MD RAID1 -- but not on a single disk.
> >
> > Andi suggested:
> >
> > Yes, I bet something forgets to turn on interrupts again and it's
> > picked up by (and blamed on) the next guy who does an unconditional
> > sti, which happens to be __do_sofitrq or idle.
> >
> > That sounds right to me.
> >
> > I built 2.6.16-rc5-git6 yesterday, and it still suffers from the same
> > issue.
> >
>
> Not sure this will help in anyway, but anyhow.
Hi
just to throw my 2c, I have a shuttle sn25p with a amd 2x 4400+, under
normal conditions I don't see any mising tick, but when I hammer the
network and the raid5 lvm I start to see missing ticks and the same
error message mentioned before. I am using debian 2.6.15 amd64
>
> I have had this system for about 6-8 months (maybe 10) now. It was
> originally a Asus A8N-SLI Deluxe with a 3200+ Athlon64. In November I
> changed to a Asus A8N-SLI Premium, and added another 1GB memory (now
> have 2GB memory). In all that time I have not had any issues with lost
> ticks, but I was hesitant to get a X2 processor due to the issue that
> some people had.
snip ..
>
> If anything might be of relevance, or you want me to try something, just
> say it. Same with extra info that might be needed.
>
>
> Regards,
>
> --
> Martin Schlemmer
>