Hi,
Sorry if this is known, I am not on the list.
I'm having an issue with lost ticks, runnign linux 2.6.20.10 on an
intel DQ965GF motherboard. For some reason this occurs with clock-like
regularity, always exactly 24 lost ticks, about every two seconds.
This is running with 250-HZ ticks, and the small pause every two seconds
is also noticeable when using the console.
running with report_lost_ticks, I see the following:
May 1 12:58:57 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:58:59 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:59:01 server kernel: time.c: Lost 25 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:59:03 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:59:07 server last message repeated 2 times
May 1 12:59:10 server kernel: time.c: Lost 24 timer tick(s)! rip handle_IRQ_event+0x19/0x55)
May 1 12:59:12 server kernel: time.c: Lost 24 timer tick(s)! rip handle_IRQ_event+0x19/0x55)
May 1 12:59:14 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:59:16 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:59:18 server kernel: time.c: Lost 24 timer tick(s)! rip handle_IRQ_event+0x19/0x55)
May 1 12:59:20 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 12:59:52 server last message repeated 15 times
May 1 13:00:51 server last message repeated 28 times
May 1 13:01:47 server last message repeated 27 times
May 1 13:01:50 server kernel: time.c: Lost 25 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
May 1 13:01:56 server last message repeated 3 times
May 1 13:01:58 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
Since the rip often mentions _spin_unlock_irqrestore, I figured maybe
someone sleeps for 25 ticks with the interrupts disabled. I tried
running with CONFIG_DEBUG_SPINLOCK_SLEEP but this did not uncover anything.
I also noticed this code in arch/x86_64/kernel/time.c. I'm not sure if it
has anything to do with my issue, but it might since I get lost_count==24...
I could not figure out what this code is trying to do though.
#ifdef CONFIG_CPU_FREQ
/* In some cases the CPU can change frequency without us noticing
Give cpufreq a change to catch up. */
if ((lost_count+1) % 25 == 0)
cpufreq_delayed_get();
#endif
I'm not sure where to go from here. Additional information about my system:
/proc/cpuinfo:
processor : 0
vendor_id : GenuineIntel
cpu family : 15
model : 6
model name : Intel(R) Pentium(R) 4 CPU 3.20GHz
stepping : 5
cpu MHz : 3196.804
cache size : 2048 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 1
fpu : yes
fpu_exception : yes
cpuid level : 6
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl est tm2 cid cx16
xtpr lahf_lm
bogomips : 6400.03
clflush size : 64
cache_alignment : 128
address sizes : 36 bits physical, 48 bits virtual
power management:
processor : 1
vendor_id : GenuineIntel
cpu family : 15
model : 6
model name : Intel(R) Pentium(R) 4 CPU 3.20GHz
stepping : 5
cpu MHz : 3196.804
cache size : 2048 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 1
fpu : yes
fpu_exception : yes
cpuid level : 6
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl est tm2 cid cx16
xtpr lahf_lm
bogomips : 6393.97
clflush size : 64
cache_alignment : 128
address sizes : 36 bits physical, 48 bits virtual
power management:
/proc/ioports:
0000-001f : dma1
0020-0021 : pic1
0040-0043 : timer0
0050-0053 : timer1
0060-006f : keyboard
0070-0077 : rtc
0080-008f : dma page reg
00a0-00a1 : pic2
00c0-00df : dma2
00f0-00ff : fpu
03c0-03df : vga+
0400-047f : 0000:00:1f.0
0400-0403 : ACPI PM1a_EVT_BLK
0404-0405 : ACPI PM1a_CNT_BLK
0408-040b : ACPI PM_TMR
0410-0415 : ACPI CPU throttle
0420-0420 : ACPI PM2_CNT_BLK
0428-042f : ACPI GPE0_BLK
0500-053f : 0000:00:1f.0
0cf8-0cff : PCI conf1
1000-1fff : PCI Bus #02
1000-100f : 0000:02:00.0
1010-1017 : 0000:02:00.0
1018-101f : 0000:02:00.0
1020-1023 : 0000:02:00.0
1024-1027 : 0000:02:00.0
2000-201f : 0000:00:1f.3
2020-203f : 0000:00:1f.2
2020-203f : ahci
2040-205f : 0000:00:1d.2
2040-205f : uhci_hcd
2060-207f : 0000:00:1d.1
2060-207f : uhci_hcd
2080-209f : 0000:00:1d.0
2080-209f : uhci_hcd
20a0-20bf : 0000:00:1a.1
20a0-20bf : uhci_hcd
20c0-20df : 0000:00:1a.0
20c0-20df : uhci_hcd
20e0-20ff : 0000:00:19.0
20e0-20ff : e1000
2400-240f : 0000:00:03.2
2410-2417 : 0000:00:1f.2
2410-2417 : ahci
2418-241f : 0000:00:1f.2
2418-241f : ahci
2420-2427 : 0000:00:03.3
2428-242f : 0000:00:03.2
2430-2437 : 0000:00:03.2
2438-243f : 0000:00:02.0
2440-2443 : 0000:00:1f.2
2440-2443 : ahci
2444-2447 : 0000:00:1f.2
2444-2447 : ahci
2448-244b : 0000:00:03.2
244c-244f : 0000:00:03.2
/proc/iomem:
00000000-0008efff : System RAM
0008f000-0009ffff : reserved
000a0000-000bffff : Video RAM area
000c0000-000c7fff : Video ROM
000cd800-000ce7ff : Adapter ROM
000ce800-000cf7ff : Adapter ROM
000f0000-000fffff : System ROM
00100000-3e583fff : System RAM
00200000-003f7a3d : Kernel code
003f7a3e-004cd18f : Kernel data
3e584000-3e590fff : reserved
3e591000-3e649fff : System RAM
3e64a000-3e6a3fff : ACPI Non-volatile Storage
3e6a4000-3e6a8fff : ACPI Tables
3e6a9000-3e6f1fff : ACPI Non-volatile Storage
3e6f2000-3e6fefff : ACPI Tables
3e6ff000-3e6fffff : System RAM
3e700000-3effffff : reserved
40000000-4fffffff : 0000:00:02.0
50000000-500fffff : PCI Bus #02
50000000-500001ff : 0000:02:00.0
50100000-501fffff : 0000:00:02.0
50200000-5021ffff : 0000:00:19.0
50200000-5021ffff : e1000
50220000-50220fff : 0000:00:19.0
50220000-50220fff : e1000
50221000-50221fff : 0000:00:03.3
50222000-502227ff : 0000:00:1f.2
50222000-502227ff : ahci
50222800-50222bff : 0000:00:1d.7
50222800-50222bff : ehci_hcd
50222c00-50222fff : 0000:00:1a.7
50222c00-50222fff : ehci_hcd
50223000-502230ff : 0000:00:1f.3
50223100-5022310f : 0000:00:03.0
50300000-503fffff : PCI Bus #01
50400000-504fffff : PCI Bus #03
50500000-505fffff : PCI Bus #04
50600000-506fffff : PCI Bus #05
fec00000-fec00fff : IOAPIC 0
fed00000-fed003ff : HPET 0
fee00000-fee00fff : Local APIC
ffe00000-ffffffff : reserved
lspci:
00:00.0 Host bridge: Intel Corporation Q963/Q965 Memory Controller Hub (rev 02)
00:02.0 VGA compatible controller: Intel Corporation Q963/Q965 Integrated Graphics Controller (rev 02)
00:03.0 Communication controller: Intel Corporation Q963/Q965 HECI Controller (rev 02)
00:03.2 IDE interface: Intel Corporation Q963/Q965 PT IDER Controller (rev 02)
00:03.3 Serial controller: Intel Corporation Q963/Q965 KT Controller (rev 02)
00:19.0 Ethernet controller: Intel Corporation 82566DM Gigabit Network Connection (rev 02)
00:1a.0 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI #4 (rev 02)
00:1a.1 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI #5 (rev 02)
00:1a.7 USB Controller: Intel Corporation 82801H (ICH8 Family) USB2 EHCI #2 (rev 02)
00:1c.0 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 1 (rev 02)
00:1c.1 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 2 (rev 02)
00:1c.2 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 3 (rev 02)
00:1c.3 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 4 (rev 02)
00:1c.4 PCI bridge: Intel Corporation 82801H (ICH8 Family) PCI Express Port 5 (rev 02)
00:1d.0 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI #1 (rev 02)
00:1d.1 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI #2 (rev 02)
00:1d.2 USB Controller: Intel Corporation 82801H (ICH8 Family) USB UHCI #3 (rev 02)
00:1d.7 USB Controller: Intel Corporation 82801H (ICH8 Family) USB2 EHCI #1 (rev 02)
00:1e.0 PCI bridge: Intel Corporation 82801 PCI Bridge (rev f2)
00:1f.0 ISA bridge: Intel Corporation 82801HO (ICH8DO) LPC Interface Controller (rev 02)
00:1f.2 SATA controller: Intel Corporation 82801HB (ICH8) SATA AHCI Controller (rev 02)
00:1f.3 SMBus: Intel Corporation 82801H (ICH8 Family) SMBus Controller (rev 02)
02:00.0 IDE interface: Marvell Technology Group Ltd. Unknown device 6101 (rev b1)
/proc/interrupts:
CPU0 CPU1
0: 68826 0 IO-APIC-edge timer
1: 30 0 IO-APIC-edge i8042
8: 1 0 IO-APIC-edge rtc
9: 0 0 IO-APIC-fasteoi acpi
12: 3 0 IO-APIC-edge i8042
16: 0 0 IO-APIC-fasteoi uhci_hcd:usb3
18: 0 0 IO-APIC-fasteoi ehci_hcd:usb1, uhci_hcd:usb7
19: 0 0 IO-APIC-fasteoi uhci_hcd:usb6
21: 0 0 IO-APIC-fasteoi uhci_hcd:usb4
23: 0 0 IO-APIC-fasteoi ehci_hcd:usb2, uhci_hcd:usb5
313: 2356 0 PCI-MSI-edge eth0
314: 2002 0 PCI-MSI-edge libata
NMI: 81 60
LOC: 68792 71817
ERR: 0
One last thing: I have another box which is fairly similar, with a
DG965RY motherboard. That other box does *not* seem to lose any ticks,
running the same kernel that works so poorly on the DQ965GF board.
Does that point to a hardware/bios issue then ?????
Please help. I dont mind trying things, but I really dont know what to
try at this point...
--
Michel "Walken" Lespinasse
"Bill Gates is a monocle and a Persian cat away from being the villain
in a James Bond movie." -- Dennis Miller
Michel Lespinasse wrote:
>
> I'm having an issue with lost ticks, runnign linux 2.6.20.10 on an
> intel DQ965GF motherboard. For some reason this occurs with clock-like
> regularity, always exactly 24 lost ticks, about every two seconds.
> This is running with 250-HZ ticks, and the small pause every two seconds
> is also noticeable when using the console.
>
>
> running with report_lost_ticks, I see the following:
>
> May 1 12:58:57 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:58:59 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:01 server kernel: time.c: Lost 25 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:03 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:07 server last message repeated 2 times
> May 1 12:59:10 server kernel: time.c: Lost 24 timer tick(s)! rip handle_IRQ_event+0x19/0x55)
> May 1 12:59:12 server kernel: time.c: Lost 24 timer tick(s)! rip handle_IRQ_event+0x19/0x55)
> May 1 12:59:14 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:16 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:18 server kernel: time.c: Lost 24 timer tick(s)! rip handle_IRQ_event+0x19/0x55)
> May 1 12:59:20 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:52 server last message repeated 15 times
> May 1 13:00:51 server last message repeated 28 times
> May 1 13:01:47 server last message repeated 27 times
> May 1 13:01:50 server kernel: time.c: Lost 25 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 13:01:56 server last message repeated 3 times
> May 1 13:01:58 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
>
>
> Since the rip often mentions _spin_unlock_irqrestore, I figured maybe
> someone sleeps for 25 ticks with the interrupts disabled. I tried
> running with CONFIG_DEBUG_SPINLOCK_SLEEP but this did not uncover anything.
>
>
> I also noticed this code in arch/x86_64/kernel/time.c. I'm not sure if it
> has anything to do with my issue, but it might since I get lost_count==24...
> I could not figure out what this code is trying to do though.
>
> #ifdef CONFIG_CPU_FREQ
> /* In some cases the CPU can change frequency without us noticing
> Give cpufreq a change to catch up. */
> if ((lost_count+1) % 25 == 0)
> cpufreq_delayed_get();
> #endif
>
>
> I'm not sure where to go from here. Additional information about my system:
>
Try disabling CONFIG_CPU_FREQ?
> One last thing: I have another box which is fairly similar, with a
> DG965RY motherboard. That other box does *not* seem to lose any ticks,
> running the same kernel that works so poorly on the DQ965GF board.
> Does that point to a hardware/bios issue then ?????
Is it running the exact same kernel, with the same cpufreq settings at
runtime (governor, controller, etc?)
(I've added the E1000 maintainers to the thread as I found the issue
seems to go away after I compile out that driver. For reference, I was
trying to figure out why I lose exactly 24 ticks about every two
seconds, as shown with report_lost_ticks. This is with a DQ965GF
motherboard with onboard E1000).
On Tue, May 01, 2007 at 11:34:28AM -0400, Chuck Ebbert wrote:
> Michel Lespinasse wrote:
> > running with report_lost_ticks, I see the following:
> >
> > May 1 12:58:57 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> > May 1 12:58:59 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> Try disabling CONFIG_CPU_FREQ?
OK, so I tried a few things.
Disabling CONFIG_CPU_FREQ does not fix the issue.
Running with 2.6.16.49 did fix the issue, but my onboard E1000 is not
detected then (I do see the 'Intel Pro/1000 network driver' message
at boot time, but ifconfig -a does not show an ethernet interface)
Going back to 2.6.20.10 with no E1000 driver (so really no
network devices at all): aaaaaah, lost ticks are gone.
I can even re-enable CONFIG_CPU_FREQ.
With 2.6.20.10, E1000 compiled in, without NAPI: I do see the lost ticks.
With 2.6.20.10, modular E1000 with NAPI: I did not get any lost ticks.
However the network did not work correctly after boot up.
The e1000 module was loaded, the routes were set etc... but I could
not ping anything. The switch lights seemed to indicate no packets
were coming out. After ifdown eth0 and ifup eth0 again, the network
came up fine, but at 100 megabit speed (full duplex) instead of gigabit.
A few log messages come up:
e1000: eth0: e1000_probe: Intel(R) PRO/1000 Network Connection
e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
e1000: eth0: e1000_watchdog: NIC Link is Down
e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex
e1000: eth0: e1000_watchdog: 10/100 speed: disabling TSO
Which is slightly strange since the box is connected to a gigabit switch.
The default kernel from debian etch, 2.6.18 based with modular e1000,
connects at gigabit speeds but loses ticks on this machine.
> > One last thing: I have another box which is fairly similar, with a
> > DG965RY motherboard. That other box does *not* seem to lose any ticks,
> > running the same kernel that works so poorly on the DQ965GF board.
> > Does that point to a hardware/bios issue then ?????
>
> Is it running the exact same kernel, with the same cpufreq settings at
> runtime (governor, controller, etc?)
I have not been running 2.6.20.10 on the DG965RY yet. However, the kernel
I use on the DG965RY (2.6.20.7 with statically compiled E1000 driver),
which does not lose ticks there, does lose ticks when I move it to the DQ965GF.
If it makes any difference, the DQ965GF is running with BIOS version 5882
dated 4/13/2007. The DG965RY runs with BIOS version 1676 (same date).
I have not changed any settings in the 'management engine' BIOS menu
(actually I have not entered it since it'd require me to set a password,
and I thought I'd avoid features I dont fully understand :)
Anything else I should try ?
Thanks,
--
Michel "Walken" Lespinasse
"Bill Gates is a monocle and a Persian cat away from being the villain
in a James Bond movie." -- Dennis Miller
Michel Lespinasse wrote:
> (I've added the E1000 maintainers to the thread as I found the issue
> seems to go away after I compile out that driver. For reference, I was
> trying to figure out why I lose exactly 24 ticks about every two
> seconds, as shown with report_lost_ticks. This is with a DQ965GF
> motherboard with onboard E1000).
that's perfectly likely. The main issue is that we read the hardware stats every
two seconds and that can consume quite some time. It's strange that you are
losing that many ticks IMHO, but losing one or two might very well be.
We've been playing with all sorts of solutions to this problem and haven't come
up with a way to reduce the load of the system reading HW stats, and it remains
the most likely culprit, allthough I don't rule out clean routines just yet.
This could very well be exaggerated at 100mbit speeds as well, I never looked at
that.
I've had good results with 2.6.21.1 (even running tickless :)) on these NICs.
Have you tried that yet?
Auke
Kok, Auke wrote:
> Michel Lespinasse wrote:
>> (I've added the E1000 maintainers to the thread as I found the issue
>> seems to go away after I compile out that driver. For reference, I was
>> trying to figure out why I lose exactly 24 ticks about every two
>> seconds, as shown with report_lost_ticks. This is with a DQ965GF
>> motherboard with onboard E1000).
>
> that's perfectly likely. The main issue is that we read the hardware
> stats every two seconds and that can consume quite some time. It's
> strange that you are losing that many ticks IMHO, but losing one or two
> might very well be.
>
> We've been playing with all sorts of solutions to this problem and
> haven't come up with a way to reduce the load of the system reading HW
> stats, and it remains the most likely culprit, allthough I don't rule
> out clean routines just yet. This could very well be exaggerated at
> 100mbit speeds as well, I never looked at that.
>
> I've had good results with 2.6.21.1 (even running tickless :)) on these
> NICs. Have you tried that yet?
Maybe this could fix it in 2.6.20? (went into 2.6.21)
--------------------------------------------------------------------------
Gitweb: http://git.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=46fcc86dd71d70211e965102fb69414c90381880
Commit: 46fcc86dd71d70211e965102fb69414c90381880
Parent: 2b858bd02ffca71391161f5709588fc70da79531
Author: Linus Torvalds <[email protected]>
AuthorDate: Thu Apr 19 18:21:01 2007 -0700
Committer: Linus Torvalds <[email protected]>
CommitDate: Thu Apr 19 18:21:01 2007 -0700
Revert "e1000: fix NAPI performance on 4-port adapters"
This reverts commit 60cba200f11b6f90f35634c5cd608773ae3721b7. It's been
linked to lockups of the e1000 hardware, see for example
https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=229603
but it's likely that the commit itself is not really introducing the
bug, but just allowing an unrelated problem to rear its ugly head (ie
one current working theory is that the code exposes us to a hardware
race condition by decreasing the amount of time we spend in each NAPI
poll cycle).
We'll revert it until root cause is known. Intel has a repeatable
reproduction on two different machines and bus traces of the hardware
doing something bad.
Chuck Ebbert wrote:
> Kok, Auke wrote:
>> Michel Lespinasse wrote:
>>> (I've added the E1000 maintainers to the thread as I found the issue
>>> seems to go away after I compile out that driver. For reference, I was
>>> trying to figure out why I lose exactly 24 ticks about every two
>>> seconds, as shown with report_lost_ticks. This is with a DQ965GF
>>> motherboard with onboard E1000).
>> that's perfectly likely. The main issue is that we read the hardware
>> stats every two seconds and that can consume quite some time. It's
>> strange that you are losing that many ticks IMHO, but losing one or two
>> might very well be.
>>
>> We've been playing with all sorts of solutions to this problem and
>> haven't come up with a way to reduce the load of the system reading HW
>> stats, and it remains the most likely culprit, allthough I don't rule
>> out clean routines just yet. This could very well be exaggerated at
>> 100mbit speeds as well, I never looked at that.
>>
>> I've had good results with 2.6.21.1 (even running tickless :)) on these
>> NICs. Have you tried that yet?
>
> Maybe this could fix it in 2.6.20? (went into 2.6.21)
well, that hasn't got anything to do with stats, but is part of the clean_tx/rx
codepath. I personally don't get any lost_ticks so I can't reproduce, but that
was why I was hinting that you can try it for us ;)
codewise, the patch below makes our cleanup routine spend _more_ time, instead
of less, which is why I think it's not the cause nor fix.
Auke
>
> --------------------------------------------------------------------------
>
> Gitweb: http://git.kernel.org/git/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=46fcc86dd71d70211e965102fb69414c90381880
> Commit: 46fcc86dd71d70211e965102fb69414c90381880
> Parent: 2b858bd02ffca71391161f5709588fc70da79531
> Author: Linus Torvalds <[email protected]>
> AuthorDate: Thu Apr 19 18:21:01 2007 -0700
> Committer: Linus Torvalds <[email protected]>
> CommitDate: Thu Apr 19 18:21:01 2007 -0700
>
> Revert "e1000: fix NAPI performance on 4-port adapters"
>
> This reverts commit 60cba200f11b6f90f35634c5cd608773ae3721b7. It's been
> linked to lockups of the e1000 hardware, see for example
>
> https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=229603
>
> but it's likely that the commit itself is not really introducing the
> bug, but just allowing an unrelated problem to rear its ugly head (ie
> one current working theory is that the code exposes us to a hardware
> race condition by decreasing the amount of time we spend in each NAPI
> poll cycle).
>
> We'll revert it until root cause is known. Intel has a repeatable
> reproduction on two different machines and bus traces of the hardware
> doing something bad.
>
On 5/1/07, Kok, Auke <[email protected]> wrote:
> Michel Lespinasse wrote:
> > (I've added the E1000 maintainers to the thread as I found the issue
> > seems to go away after I compile out that driver. For reference, I was
> > trying to figure out why I lose exactly 24 ticks about every two
> > seconds, as shown with report_lost_ticks. This is with a DQ965GF
> > motherboard with onboard E1000).
>
> that's perfectly likely. The main issue is that we read the hardware stats every
> two seconds and that can consume quite some time. It's strange that you are
> losing that many ticks IMHO, but losing one or two might very well be.
>
Why do you have to disable all interrupts? Shouldn't it be sufficient
to disable interrupts on the e1000 only?
Lee
On Tue, May 01, 2007 at 03:08:48PM -0700, Kok, Auke wrote:
> Michel Lespinasse wrote:
> >(I've added the E1000 maintainers to the thread as I found the issue
> >seems to go away after I compile out that driver. For reference, I was
> >trying to figure out why I lose exactly 24 ticks about every two
> >seconds, as shown with report_lost_ticks. This is with a DQ965GF
> >motherboard with onboard E1000).
>
> that's perfectly likely. The main issue is that we read the hardware stats
> every two seconds and that can consume quite some time. It's strange that
> you are losing that many ticks IMHO, but losing one or two might very well
> be.
Ah, interesting.
So, I dived a bit deeper and added printk's all over the place to
trace what's going on. Here is what I'm seeing.
For some reason (I suppose something wrong in the hardware init code ???)
e1000_get_software_flag() does not succeed. It just loops PHY_CFG_TIMEOUT=100
times, sleeping 1ms each with mdelay(1), and then returns (after 100ms)
with an exit code of -E1000_ERR_CONFIG.
Because of that, e1000_read_phy_reg() does not succeed:
it calls e1000_swfw_sync_acquire -> e1000_get_software_flag and then
returns -E1000_ERR_SWFW_SYNC
On my system, every e1000_watchdog() invocation calls e1000_read_phy_reg()
twice: first near the top of e1000_check_for_link() within the
e1000_media_type_copper && hw->get_link_status condition, then within
e1000_update_stats() to read and update the idle_errors statistic.
Each call results in a 100ms delay. The second call is enclosed within
an spin_lock_irqsave()..spin_unlock_irqrestore() section, so it results
in 100ms of lost ticks too.
Now I have no idea how to fix that, but it does seem like it must be an
initialisation issue. Possibly it might be a matter of telling the firmware
"management engine" to keep its paws off of the adapter, I dont know.
If you want me to add logging within the init functions, let me know.
The other operations - like all the E1000_READ_REG() calls within
e1000_update_stats() - seem to take negligible time compared to the
two failing e1000_read_phy_reg() calls.
> I've had good results with 2.6.21.1 (even running tickless :)) on these
> NICs. Have you tried that yet?
Not yet. Coming up... I'd prefer not to rely on new kernels at this
point though - but I can certainly try it just to report on current status.
--
Michel "Walken" Lespinasse
"Bill Gates is a monocle and a Persian cat away from being the villain
in a James Bond movie." -- Dennis Miller
Michel Lespinasse <[email protected]> writes:
>
> running with report_lost_ticks, I see the following:
>
> May 1 12:58:57 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:58:59 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:01 server kernel: time.c: Lost 25 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
> May 1 12:59:03 server kernel: time.c: Lost 24 timer tick(s)! rip _spin_unlock_irqrestore+0x8/0x9)
This means some code disabled interrupts using a spinlock for far too long.
Can you add a dump_stack() in arch/x86_64/kernel/time.c:handle_lost_ticks()? That should
tell the culprit
-Andi
Michel Lespinasse wrote:
> On my system, every e1000_watchdog() invocation calls e1000_read_phy_reg()
> twice: first near the top of e1000_check_for_link() within the
> e1000_media_type_copper && hw->get_link_status condition, then within
> e1000_update_stats() to read and update the idle_errors statistic.
> Each call results in a 100ms delay. The second call is enclosed within
> an spin_lock_irqsave()..spin_unlock_irqrestore() section, so it results
> in 100ms of lost ticks too.
Unfortunately we need the spinlock here. I'm not 100% sure the irqsave is no
longer needed since we recently modified the watchdog to run as a task (out of
interrupt context), but this code hasn't made it upstream yet (it's sitting in
mm if you're interested).
> Now I have no idea how to fix that, but it does seem like it must be an
> initialisation issue. Possibly it might be a matter of telling the firmware
> "management engine" to keep its paws off of the adapter, I dont know.
> If you want me to add logging within the init functions, let me know.
please don't, see below
> The other operations - like all the E1000_READ_REG() calls within
> e1000_update_stats() - seem to take negligible time compared to the
> two failing e1000_read_phy_reg() calls.
>
>> I've had good results with 2.6.21.1 (even running tickless :)) on these
>> NICs. Have you tried that yet?
>
> Not yet. Coming up... I'd prefer not to rely on new kernels at this
> point though - but I can certainly try it just to report on current status.
I currently suspect that (on this NIC) you're being bitten by a initialization
bug that was fixed in later patches that made it into 2.6.21. The best thing to
try for you is attempt to run 2.6.21 in the same configuration and see if that
fixes it for you. It has to do with a patch I sent to fix the firmware takeover
bits at startup, something that was definately broken in 2.6.19 and probably 2.6.20.
Auke
Michel Lespinasse wrote:
>> I've had good results with 2.6.21.1 (even running tickless :)) on these
>> NICs. Have you tried that yet?
>
> Not yet. Coming up... I'd prefer not to rely on new kernels at this
> point though - but I can certainly try it just to report on current status.
I just checked and the fix I was referring to earlier didn't make it into
2.6.21-final. You can get 2.6.21-git1 from kernel.org which has the fix. See
http://www.kernel.org/pub/linux/kernel/v2.6/snapshots/patch-2.6.21-git1.log
for the changelog and commit id's for the patch:
commit c58b8e4a25a1ba347a0e5d21984c97bd296f1691
Merge: afc2e82... f50393f...
Author: Linus Torvalds <[email protected]>
Date: Fri Apr 27 10:14:53 2007 -0700
Merge branch 'e1000-fixes' of
master.kernel.org:/pub/scm/linux/kernel/git/jgarzik/netdev-2.6
* 'e1000-fixes' of
master.kernel.org:/pub/scm/linux/kernel/git/jgarzik/netdev-2.6:
e1000: FIX: Stop raw interrupts disabled nag from RT
e1000: FIX: firmware handover bits
e1000: FIX: be ready for incoming irq at pci_request_irq
Please give this a try and see if it resolves your issues.
hth,
Auke
On Wed, May 02, 2007 at 11:14:52AM -0700, Kok, Auke wrote:
> I just checked and the fix I was referring to earlier didn't make it into
> 2.6.21-final. You can get 2.6.21-git1 from kernel.org which has the fix. See
>
> http://www.kernel.org/pub/linux/kernel/v2.6/snapshots/patch-2.6.21-git1.log
Good. So I tried that patch (well, actually only the change visible at
http://lkml.org/lkml/2007/3/6/268). I patched it into a 2.6.20.11 kernel,
using the same config file as previously. The good news is that this fixes
my issue: there are no lost ticks anymore, and the link does negotiate a
gigabit connection. This is a great improvement for me :)
I still seem to hit an issue if using the ethtool command, though.
when using 'ethtool -s eth0 autoneg on', the link comes up at gigabit speed,
but a couple seconds later is comes down again, and then up at 100 megabits:
e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
e1000: eth0: e1000_watchdog: NIC Link is Down
e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex
e1000: eth0: e1000_watchdog: 10/100 speed: disabling TSO
The same thing happens if I use ifdown eth0; ifup eth0 too. Once again,
I only observe this on my DQ965GF motherboard, the DG965RY board is fine
(stays at gigabit speed when I issue these commands).
Is this something you could easily reproduce at Intel or would you want me
to look into that issue on my system ?
Thanks,
--
Michel "Walken" Lespinasse
"Bill Gates is a monocle and a Persian cat away from being the villain
in a James Bond movie." -- Dennis Miller
[Adding Bruce to the Cc, reply below]
Michel Lespinasse wrote:
> On Wed, May 02, 2007 at 11:14:52AM -0700, Kok, Auke wrote:
>> I just checked and the fix I was referring to earlier didn't make it into
>> 2.6.21-final. You can get 2.6.21-git1 from kernel.org which has the fix. See
>>
>> http://www.kernel.org/pub/linux/kernel/v2.6/snapshots/patch-2.6.21-git1.log
>
> Good. So I tried that patch (well, actually only the change visible at
> http://lkml.org/lkml/2007/3/6/268). I patched it into a 2.6.20.11 kernel,
> using the same config file as previously. The good news is that this fixes
> my issue: there are no lost ticks anymore, and the link does negotiate a
> gigabit connection. This is a great improvement for me :)
>
> I still seem to hit an issue if using the ethtool command, though.
> when using 'ethtool -s eth0 autoneg on', the link comes up at gigabit speed,
> but a couple seconds later is comes down again, and then up at 100 megabits:
>
> e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
> e1000: eth0: e1000_watchdog: NIC Link is Down
> e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex
> e1000: eth0: e1000_watchdog: 10/100 speed: disabling TSO
>
> The same thing happens if I use ifdown eth0; ifup eth0 too. Once again,
> I only observe this on my DQ965GF motherboard, the DG965RY board is fine
> (stays at gigabit speed when I issue these commands).
>
> Is this something you could easily reproduce at Intel or would you want me
> to look into that issue on my system ?
I think we have confirmed this issue and I'll work with Bruce on seeing where
the fix went. I might give you another patch to try.
Auke
Yes, this was discovered through code inspection last week and I've
already made a fix (as I mentioned to Auke off-thread). It should be
submitted upstream shortly.
-----Original Message-----
From: Kok, Auke [mailto:[email protected]]
Sent: Thursday, May 03, 2007 8:37 AM
To: Michel Lespinasse
Cc: Kok, Auke-jan H; Chuck Ebbert; [email protected]; Dave
Jones; cramerj; Ronciak, John; Brandeburg, Jesse; Kirsher, Jeffrey T;
Allan, Bruce W
Subject: Re: e1000 issue on DQ965GF board (was 24 lost ticks with
2.6.20.10 kernel)
[Adding Bruce to the Cc, reply below]
Michel Lespinasse wrote:
> On Wed, May 02, 2007 at 11:14:52AM -0700, Kok, Auke wrote:
>> I just checked and the fix I was referring to earlier didn't make it
into
>> 2.6.21-final. You can get 2.6.21-git1 from kernel.org which has the
fix. See
>>
>>
http://www.kernel.org/pub/linux/kernel/v2.6/snapshots/patch-2.6.21-git1.
log
>
> Good. So I tried that patch (well, actually only the change visible at
> http://lkml.org/lkml/2007/3/6/268). I patched it into a 2.6.20.11
kernel,
> using the same config file as previously. The good news is that this
fixes
> my issue: there are no lost ticks anymore, and the link does negotiate
a
> gigabit connection. This is a great improvement for me :)
>
> I still seem to hit an issue if using the ethtool command, though.
> when using 'ethtool -s eth0 autoneg on', the link comes up at gigabit
speed,
> but a couple seconds later is comes down again, and then up at 100
megabits:
>
> e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
> e1000: eth0: e1000_watchdog: NIC Link is Down
> e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex
> e1000: eth0: e1000_watchdog: 10/100 speed: disabling TSO
>
> The same thing happens if I use ifdown eth0; ifup eth0 too. Once
again,
> I only observe this on my DQ965GF motherboard, the DG965RY board is
fine
> (stays at gigabit speed when I issue these commands).
>
> Is this something you could easily reproduce at Intel or would you
want me
> to look into that issue on my system ?
I think we have confirmed this issue and I'll work with Bruce on seeing
where
the fix went. I might give you another patch to try.
Auke
Michel Lespinasse wrote:
> On Wed, May 02, 2007 at 11:14:52AM -0700, Kok, Auke wrote:
>> I just checked and the fix I was referring to earlier didn't make it into
>> 2.6.21-final. You can get 2.6.21-git1 from kernel.org which has the fix. See
>>
>> http://www.kernel.org/pub/linux/kernel/v2.6/snapshots/patch-2.6.21-git1.log
>
> Good. So I tried that patch (well, actually only the change visible at
> http://lkml.org/lkml/2007/3/6/268). I patched it into a 2.6.20.11 kernel,
> using the same config file as previously. The good news is that this fixes
> my issue: there are no lost ticks anymore, and the link does negotiate a
> gigabit connection. This is a great improvement for me :)
>
> I still seem to hit an issue if using the ethtool command, though.
> when using 'ethtool -s eth0 autoneg on', the link comes up at gigabit speed,
> but a couple seconds later is comes down again, and then up at 100 megabits:
>
> e1000: eth0: e1000_watchdog: NIC Link is Up 1000 Mbps Full Duplex
> e1000: eth0: e1000_watchdog: NIC Link is Down
> e1000: eth0: e1000_watchdog: NIC Link is Up 100 Mbps Full Duplex
> e1000: eth0: e1000_watchdog: 10/100 speed: disabling TSO
>
> The same thing happens if I use ifdown eth0; ifup eth0 too. Once again,
> I only observe this on my DQ965GF motherboard, the DG965RY board is fine
> (stays at gigabit speed when I issue these commands).
>
> Is this something you could easily reproduce at Intel or would you want me
> to look into that issue on my system ?
can you try turning off the "management enable" function in the BIOS of the
DQ965GF? That fixes this issue for us in our labs. A fix for this is also
available in our standalone 7.5.5.1 driver (obtainable from e1000.sf.net), but
it hasn't made it upstream yet.
Auke
On Fri, May 04, 2007 at 11:25:43AM -0700, Kok, Auke wrote:
> can you try turning off the "management enable" function in the BIOS of the
> DQ965GF? That fixes this issue for us in our labs. A fix for this is also
> available in our standalone 7.5.5.1 driver (obtainable from e1000.sf.net),
> but it hasn't made it upstream yet.
Done. Indeed, this fixed the issue. Thanks!
The interesting thing is that I *thought* I had it off, as I had never
touched this menu or set a password on it. The manual said that the board
would not be accessible from the network until I set a password, which I
had (incorrectly) assumed to mean the ME feature would be off. To turn off
the option (or even see I had it on) I had to google for the default
ME password, which turned out to be 'admin'.
Thanks for the help,
--
Michel "Walken" Lespinasse
"Bill Gates is a monocle and a Persian cat away from being the villain
in a James Bond movie." -- Dennis Miller