I'm performing realtime latency tests (for details about the hardware
and software, see my mail "[BUG] 2.6.11: Random SCSI/USB errors when
reading from USB memory stick" erlier today).
Even when the errors described in my previous mail does not occur,
massive USB stick transfers cause latencies of 1 to 2 milliseconds,
which is way too much for realtime control systems.
I observe these latencies on a vanilla 2.6.11 at any rtprio (even 99),
and on realtime-preempt-2.6.12-rc1-V0.7.41-11 at low rtprio (1). When
running the program on realtime-preempt-2.6.12-rc1-V0.7.41-11 with
rtprio 99, the latencies are gone, but using a rtprio higher than the
interrupt handlers is not realistic.
Is there anything which can be done about it?
Klaus Kusche
> Entwicklung Software - Steuerung
> Software Development - Control
>
> KEBA AG
> A-4041 Linz
> Gewerbepark Urfahr
> Tel +43 / 732 / 7090-3120
> Fax +43 / 732 / 7090-8919
> E-Mail: [email protected]
> http://www.keba.com
>
>
On Wed, 30 Mar 2005, kus Kusche Klaus wrote:
> I'm performing realtime latency tests (for details about the hardware
> and software, see my mail "[BUG] 2.6.11: Random SCSI/USB errors when
> reading from USB memory stick" erlier today).
>
> Even when the errors described in my previous mail does not occur,
> massive USB stick transfers cause latencies of 1 to 2 milliseconds,
> which is way too much for realtime control systems.
>
> I observe these latencies on a vanilla 2.6.11 at any rtprio (even 99),
> and on realtime-preempt-2.6.12-rc1-V0.7.41-11 at low rtprio (1). When
> running the program on realtime-preempt-2.6.12-rc1-V0.7.41-11 with
> rtprio 99, the latencies are gone, but using a rtprio higher than the
> interrupt handlers is not realistic.
>
> Is there anything which can be done about it?
The latencies are almost certainly caused by the USB host controller
driver. I'm planning improvements to uhci-hcd which should help reduce
the latency, but it will still be on the large side. And I won't have
time to write the changes to the driver for several months.
The best solution is to stop using uhci-hcd. Get a PCI card with an OHCI
or EHCI (high-speed) controller. They do much more work in hardware,
reducing the amount of time the driver needs to spend with interrupts
disabled.
Alan Stern
On Wed, 2005-03-30 at 10:55 -0500, Alan Stern wrote:
> On Wed, 30 Mar 2005, kus Kusche Klaus wrote:
>
> > I'm performing realtime latency tests (for details about the hardware
> > and software, see my mail "[BUG] 2.6.11: Random SCSI/USB errors when
> > reading from USB memory stick" erlier today).
> >
> > Even when the errors described in my previous mail does not occur,
> > massive USB stick transfers cause latencies of 1 to 2 milliseconds,
> > which is way too much for realtime control systems.
> >
> > I observe these latencies on a vanilla 2.6.11 at any rtprio (even 99),
> > and on realtime-preempt-2.6.12-rc1-V0.7.41-11 at low rtprio (1). When
> > running the program on realtime-preempt-2.6.12-rc1-V0.7.41-11 with
> > rtprio 99, the latencies are gone, but using a rtprio higher than the
> > interrupt handlers is not realistic.
> >
> > Is there anything which can be done about it?
>
> The latencies are almost certainly caused by the USB host controller
> driver. I'm planning improvements to uhci-hcd which should help reduce
> the latency, but it will still be on the large side. And I won't have
> time to write the changes to the driver for several months.
>
> The best solution is to stop using uhci-hcd. Get a PCI card with an OHCI
> or EHCI (high-speed) controller. They do much more work in hardware,
> reducing the amount of time the driver needs to spend with interrupts
> disabled.
I think this is connected to a problem people have been reporting on the
Linux audio lists. With some USB chipsets, USB audio interfaces just
don't work. There are dropouts even at very high latencies. It appears
that interrupts are being disabled for many milliseconds. PREEMPT_RT
does not help the problem. We have pretty much decided it has to be the
kernel's fault. The problem should be fixable because it seems to work
on the other OS.
Maybe we can isolate it to a certain USB chipsets. I'll try to get more
info.
Lee
Quoth [email protected]:
> Even when the errors described in my previous mail does not occur,
> massive USB stick transfers cause latencies of 1 to 2 milliseconds,
> which is way too much for realtime control systems.
I couldn't find that previous email in the MARC archives.
Regardless, you'd have to provide a small bit of information about
your hardware configuration. What device speed: full or high?
What controller: EHCI, OHCI, UHCI, something else? Which driver
for the stick: usb-storage, or ub? What else was using memory
and PCI bandwidth at the time? SMP?
Quoth [email protected]:
> I think this is connected to a problem people have been reporting on the
> Linux audio lists. With some USB chipsets, USB audio interfaces just
> don't work. There are dropouts even at very high latencies.
Well, I'd not yet expect USB audio to work over EHCI quite yet,
though one of the patches Greg just posted should help some of
the issues with full speed iso through USB 2.0 hubs. (At least
for OUT transfers as to speakers.)
You might consider reporting such issues on the Linux-USB list.
It's been ages since anyone reported such a bug with the OHCI
or UHCI drivers ... probably why folk have assumed there are
no problems there.
Something to consider specifically with audio. That uses the
isochronous transfer mode, reserving USB bandwidth. But I've
certainly seen systems with PCI busses that are severely clogged,
so that the USB controllers have a hard time accessing main
memory. Even a perfectly functional USB stack will have a hard
time with such hardware!
- Dave
On Wed, 2005-03-30 at 14:57 -0800, David Brownell wrote:
> Quoth [email protected]:
> > I think this is connected to a problem people have been reporting on the
> > Linux audio lists. With some USB chipsets, USB audio interfaces just
> > don't work. There are dropouts even at very high latencies.
Please don't trim cc: lists. Always use reply-to-all for LKML mail.
Thanks,
Lee
[cc list restored]
On Wed, 2005-03-30 at 14:57 -0800, David Brownell wrote:
> Quoth [email protected]:
> > I think this is connected to a problem people have been reporting on the
> > Linux audio lists. With some USB chipsets, USB audio interfaces just
> > don't work. There are dropouts even at very high latencies.
>
> Well, I'd not yet expect USB audio to work over EHCI quite yet,
> though one of the patches Greg just posted should help some of
> the issues with full speed iso through USB 2.0 hubs. (At least
> for OUT transfers as to speakers.)
>
This is the exact configuration of one of the users who reported the
problem on LAU. Got a pointer to the patch? And what's the issue with
IN transfers?
> You might consider reporting such issues on the Linux-USB list.
> It's been ages since anyone reported such a bug with the OHCI
> or UHCI drivers ... probably why folk have assumed there are
> no problems there.
>
OK, good to know.
>
> Something to consider specifically with audio. That uses the
> isochronous transfer mode, reserving USB bandwidth. But I've
> certainly seen systems with PCI busses that are severely clogged,
> so that the USB controllers have a hard time accessing main
> memory. Even a perfectly functional USB stack will have a hard
> time with such hardware!
Unlikely because it works under Windows. We're not all that far behind
however; USB audio on that OS did not really work until XP SP1. Also,
if that were a widespread problem we would be seeing problems with PCI
devices too.
Also please fix the threading in your email client.
Lee
On Wednesday 30 March 2005 4:43 pm, Lee Revell wrote:
> On Wed, 2005-03-30 at 14:57 -0800, David Brownell wrote:
> > Quoth [email protected]:
> > > I think this is connected to a problem people have been reporting on the
> > > Linux audio lists. With some USB chipsets, USB audio interfaces just
> > > don't work. There are dropouts even at very high latencies.
>
> Please don't trim cc: lists. Always use reply-to-all for LKML mail.
Please don't assume everyone subscribes to LKML, or that
everything crafted to be threaded more-or-less-correctly
was really crafted with any kind of "reply" command. :)
On Wed, 2005-03-30 at 17:13 -0800, David Brownell wrote:
> On Wednesday 30 March 2005 4:43 pm, Lee Revell wrote:
> > On Wed, 2005-03-30 at 14:57 -0800, David Brownell wrote:
> > > Quoth [email protected]:
> > > > I think this is connected to a problem people have been reporting on the
> > > > Linux audio lists. With some USB chipsets, USB audio interfaces just
> > > > don't work. There are dropouts even at very high latencies.
> >
> > Please don't trim cc: lists. Always use reply-to-all for LKML mail.
>
> Please don't assume everyone subscribes to LKML, or that
> everything crafted to be threaded more-or-less-correctly
> was really crafted with any kind of "reply" command. :)
Um, that's exactly why reply-to-all should be used, because not everyone
who posts to LKML subscribes to the list. Otherwise, you'd either have
to make everyone who posts a question or a bug report subscribe to the
list to see the replies, or place the burden on the responder to keep
track of who wants to be cc'ed and who doesn't.
Beaised, even if you disagree with them, when you post to LKML you abide
by the LKML rules. It's up to you to know what those are.
Lee
On Wednesday 30 March 2005 4:51 pm, Lee Revell wrote:
> [cc list restored]
Thanks, I never had one to start with ... :)
> On Wed, 2005-03-30 at 14:57 -0800, David Brownell wrote:
> > Quoth [email protected]:
> > > I think this is connected to a problem people have been reporting on the
> > > Linux audio lists. With some USB chipsets, USB audio interfaces just
> > > don't work. There are dropouts even at very high latencies.
> >
> > Well, I'd not yet expect USB audio to work over EHCI quite yet,
> > though one of the patches Greg just posted should help some of
> > the issues with full speed iso through USB 2.0 hubs. (At least
> > for OUT transfers as to speakers.)
> >
>
> This is the exact configuration of one of the users who reported the
> problem on LAU. Got a pointer to the patch? And what's the issue with
> IN transfers?
This is what Greg just posted (and Linus merged into BK, so it'll be
in BK snapshots starting tomorrow):
http://marc.theaimsgroup.com/?l=linux-usb-devel&m=111221966815043&w=2
The issue with IN transfers is that microframe scheduling is ... tricky.
One must track all kinds of stuff (which TTs are involved, which microframes
are busy, how busy they are, how much non-TT bandwidth is available). And
the relevant EHCI data structures are almost as irregular as the USB trees
one must cope with.
Plus one must have the time to spend debugging and fixing the problems, stress
testing the fixes, and devices that will trigger the problems. I've had none
of those, for quite some time now. (My particular USB speakers have pretty much
always worked on Linux, even through a USB 2.0 hub.)
Karsten has some not-ready-for-prime-time patches which he's posted
recently. They basically hardwire some of the scheduling outputs well
enough to get some of his IN transfers to work. Maybe he'll be nice
enough to repost them against current BK (they include the patch above).
I'd like to see all that split ISO stuff working with EHCI, but someone
else is going to have to do most of the work. Once it's working we can
take the CONFIG_EXPERIMENTAL off, which will remove another source of
errors. :)
- Dave
> > Please don't assume everyone subscribes to LKML, or that
> > everything crafted to be threaded more-or-less-correctly
> > was really crafted with any kind of "reply" command. :)
>
> Um, that's exactly why reply-to-all should be used,
There you go, assuming that there was a message to which a
"reply-to-all" would apply. MARC, like many archives,
doesn't provide such a CC list.
On Wed, 2005-03-30 at 17:28 -0800, David Brownell wrote:
> On Wednesday 30 March 2005 4:51 pm, Lee Revell wrote:
> > [cc list restored]
>
> Thanks, I never had one to start with ... :)
>
>
Thank you. Sorry for the tone of my reply...
> > On Wed, 2005-03-30 at 14:57 -0800, David Brownell wrote:
> > > Quoth [email protected]:
> > > > I think this is connected to a problem people have been reporting on the
> > > > Linux audio lists. With some USB chipsets, USB audio interfaces just
> > > > don't work. There are dropouts even at very high latencies.
> > >
> > > Well, I'd not yet expect USB audio to work over EHCI quite yet,
> > > though one of the patches Greg just posted should help some of
> > > the issues with full speed iso through USB 2.0 hubs. (At least
> > > for OUT transfers as to speakers.)
> > >
> >
> > This is the exact configuration of one of the users who reported the
> > problem on LAU. Got a pointer to the patch? And what's the issue with
> > IN transfers?
>
> This is what Greg just posted (and Linus merged into BK, so it'll be
> in BK snapshots starting tomorrow):
>
> http://marc.theaimsgroup.com/?l=linux-usb-devel&m=111221966815043&w=2
>
> The issue with IN transfers is that microframe scheduling is ... tricky.
> One must track all kinds of stuff (which TTs are involved, which microframes
> are busy, how busy they are, how much non-TT bandwidth is available). And
> the relevant EHCI data structures are almost as irregular as the USB trees
> one must cope with.
>
> Plus one must have the time to spend debugging and fixing the problems, stress
> testing the fixes, and devices that will trigger the problems. I've had none
> of those, for quite some time now. (My particular USB speakers have pretty much
> always worked on Linux, even through a USB 2.0 hub.)
>
> Karsten has some not-ready-for-prime-time patches which he's posted
> recently. They basically hardwire some of the scheduling outputs well
> enough to get some of his IN transfers to work. Maybe he'll be nice
> enough to repost them against current BK (they include the patch above).
>
Thanks for the explanation. I found this patch, and sent the link to
the LAU posters with the problem.
There are apparently many users affected (some gave up and went back to
2.4), so there's good opportunity for testing.
> I'd like to see all that split ISO stuff working with EHCI, but someone
> else is going to have to do most of the work. Once it's working we can
> take the CONFIG_EXPERIMENTAL off, which will remove another source of
> errors. :)
Thanks again for your help, I'll report any interesting results.
Lee
On Wed, 2005-03-30 at 17:28 -0800, David Brownell wrote:
> This is what Greg just posted (and Linus merged into BK, so it'll be
> in BK snapshots starting tomorrow):
>
> http://marc.theaimsgroup.com/?l=linux-usb-devel&m=111221966815043&w=2
Wow, just checked my mail and there were at least 5 threads just from
the past few weeks about this problem on various Linux audio lists. I
guess we'll see real soon if it helps.
Lee
On Wednesday 30 March 2005 5:32 pm, Lee Revell wrote:
> On Wed, 2005-03-30 at 17:28 -0800, David Brownell wrote:
> > On Wednesday 30 March 2005 4:51 pm, Lee Revell wrote:
> > >
> > > This is the exact configuration of one of the users who reported the
> > > problem on LAU. Got a pointer to the patch? And what's the issue with
> > > IN transfers?
> >
> > This is what Greg just posted (and Linus merged into BK, so it'll be
> > in BK snapshots starting tomorrow):
> >
> > http://marc.theaimsgroup.com/?l=linux-usb-devel&m=111221966815043&w=2
> >
> > The issue with IN transfers is that microframe scheduling is ... tricky.
> > ...
>
> Thanks for the explanation. I found this patch, and sent the link to
> the LAU posters with the problem.
>
> There are apparently many users affected (some gave up and went back to
> 2.4), so there's good opportunity for testing.
Yes. That's why I was particularly glad to see the patches from Karsten;
they were the first ones that actually got "it works for me now!!" reports.
With luck, all full speed ISO-OUT transfers will now work through EHCI.
Even through the funky multi-TT hubs from Cypress. My main question is
whether this is also true of the TDI (nee ARC) EHCI silicon that's being
embedded in various non-PCI chips.
This all seems off-topic for latency though. :)
- Dave
> > I'd like to see all that split ISO stuff working with EHCI, but someone
> > else is going to have to do most of the work. Once it's working we can
> > take the CONFIG_EXPERIMENTAL off, which will remove another source of
> > errors. :)
>
> Thanks again for your help, I'll report any interesting results.
>
> Lee
>
>
On Wed, 2005-03-30 at 17:40 -0800, David Brownell wrote:
> This all seems off-topic for latency though. :)
>
Disagree, in the bug reports I saw from JACK users the symptoms are
exactly the same as a kernel latency problem. The only clear hint that
it's something else is that the RT kernel and mainline are equally
affected.
Lee
> The latencies are almost certainly caused by the USB host controller
> driver. I'm planning improvements to uhci-hcd which should
> help reduce
> the latency, but it will still be on the large side. And I
> won't have
> time to write the changes to the driver for several months.
Any numbers about the expected "large side"?
We would need <30 microseconds irq latency,
and <<1 milliseconds rt application latency.
> The best solution is to stop using uhci-hcd. Get a PCI card
> with an OHCI
> or EHCI (high-speed) controller. They do much more work in hardware,
> reducing the amount of time the driver needs to spend with interrupts
> disabled.
The hardware is invariable. It is an embedded system with no PCI slots.
And it seems to be possible with UHCI,
because vxWorks allows USB stick transfers in operation without
missing latency requirements.
I do not require rt on the USB, it may block its own irq as long as
it likes, but it should not affect other irqs.
--
Klaus Kusche
Entwicklung Software - Steuerung
Software Development - Control
KEBA AG
A-4041 Linz
Gewerbepark Urfahr
Tel +43 / 732 / 7090-3120
Fax +43 / 732 / 7090-8919
E-Mail: [email protected]
http://www.keba.com
* kus Kusche Klaus <[email protected]> wrote:
> I'm performing realtime latency tests (for details about the hardware
> and software, see my mail "[BUG] 2.6.11: Random SCSI/USB errors when
> reading from USB memory stick" erlier today).
>
> Even when the errors described in my previous mail does not occur,
> massive USB stick transfers cause latencies of 1 to 2 milliseconds,
> which is way too much for realtime control systems.
do these occur under PREEMPT_RT? If yes, do you get any useful trace if
you enable all the tracing options but keep wakeup-timing off:
# CONFIG_WAKEUP_TIMING is not set
CONFIG_PREEMPT_TRACE=y
CONFIG_CRITICAL_PREEMPT_TIMING=y
CONFIG_CRITICAL_IRQSOFF_TIMING=y
CONFIG_CRITICAL_TIMING=y
CONFIG_LATENCY_TIMING=y
CONFIG_LATENCY_TRACE=y
CONFIG_MCOUNT=y
this should catch any type of preempt-off section, irqs-off and
preempt_disable() alike. (unless the tracer has a bug.)
(WAKEUP_TIMING is useful and lightweight but if all other tracing
features are enabled it's a bit pointless, and a bit less accurate.)
Ingo
> I couldn't find that previous email in the MARC archives.
>
> Regardless, you'd have to provide a small bit of information about
> your hardware configuration. What device speed: full or high?
> What controller: EHCI, OHCI, UHCI, something else? Which driver
> for the stick: usb-storage, or ub? What else was using memory
> and PCI bandwidth at the time? SMP?
The error occurred on an intel Pentium 3 (500 MHz) embedded system with
440BX chipset and 192 MB RAM. USB is handled by the 440BX (intel 82371
PIIX4). The UHCI driver shares interrupt 7 with an intel 82559ER 100
Mbit ethernet controller (which is driven by the e100 driver and active:
As there is no local keyboard, I access the system by ssh).
The system "disk" is a 128 MB CF card directly connected to the 440BX
primary IDE port and running in PIO mode 2 at about 2 MB/sec peak (but
it is idle most of the time). There is a SM712 VGA chip running in text
mode, a 1000 HZ std PC timer, and no other "interesting" device (nothing
else on the PCI bus or causing any interrupts).
The error was reproduced with statically linked (no modules)
vanilla-2.6.11, 2.6.11-gentoo-r3, and
realtime-preempt-2.6.12-rc1-V0.7.41-11 kernels, all built with gcc
3.4.3. No SMP. USB-storage for the sticks.
I tried with two different sticks (an old 64 MB USB 1.x and a 1 GB USB
2.x), both show the same problem on all USB interfaces on the target.
The same dd command works fine on both sticks on my office PC.
--
Klaus Kusche
Entwicklung Software - Steuerung
Software Development - Control
KEBA AG
A-4041 Linz
Gewerbepark Urfahr
Tel +43 / 732 / 7090-3120
Fax +43 / 732 / 7090-8919
E-Mail: [email protected]
http://www.keba.com
On Thu, 31 Mar 2005, kus Kusche Klaus wrote:
> > The latencies are almost certainly caused by the USB host controller
> > driver. I'm planning improvements to uhci-hcd which should
> > help reduce
> > the latency, but it will still be on the large side. And I
> > won't have
> > time to write the changes to the driver for several months.
>
> Any numbers about the expected "large side"?
> We would need <30 microseconds irq latency,
> and <<1 milliseconds rt application latency.
It's pretty hard to say, considering that: (1) None of the code has been
written yet; (2) It's impossible to say how big a difference new code will
make just by reading it -- you have to actually test it; and (3) I don't
have any hardware suitable for testing latencies.
The biggest advantage would come from using a bottom-half handler to do
most of the work. Right now the uhci-hcd driver does everything in its
interrupt handler. This would certainly help IRQ latency; it might not
affect application latency very much.
I'll try adding a bottom half in my next series of patches. Maybe it will
be ready in time to appear in the -mm kernels before 2.6.12-final is
released.
> > The best solution is to stop using uhci-hcd. Get a PCI card
> > with an OHCI
> > or EHCI (high-speed) controller. They do much more work in hardware,
> > reducing the amount of time the driver needs to spend with interrupts
> > disabled.
>
> The hardware is invariable. It is an embedded system with no PCI slots.
>
> And it seems to be possible with UHCI,
> because vxWorks allows USB stick transfers in operation without
> missing latency requirements.
>
> I do not require rt on the USB, it may block its own irq as long as
> it likes, but it should not affect other irqs.
We'll see what happens with the upcoming changes. Maybe you'll be able to
test them for me?
Alan Stern
> > > The latencies are almost certainly caused by the USB host
> controller
> > > driver. I'm planning improvements to uhci-hcd which should
> > > help reduce
> > > the latency, but it will still be on the large side. And I
> > > won't have
> > > time to write the changes to the driver for several months.
> >
> > Any numbers about the expected "large side"?
> > We would need <30 microseconds irq latency,
> > and <<1 milliseconds rt application latency.
>
> The biggest advantage would come from using a bottom-half
> handler to do
> most of the work. Right now the uhci-hcd driver does
> everything in its
> interrupt handler. This would certainly help IRQ latency; it
> might not
> affect application latency very much.
Sounds very reasonable, thanks. Also helps application latency,
because with the RT patches, I can tune the rt prio of softirq
execution (that's where bottom-half goes, doesn't it?) w.r.t. the
rt prio of the application threads.
However, if I understand things correctly, if you really need
to disable all interrupts while doing the USB work, it will not
make any difference if IRQs are disabled while you are in the
USB IRQ handler, or if they are disabled for the same amount of
work/time in the bottom-half code.
> I'll try adding a bottom half in my next series of patches.
> Maybe it will
> be ready in time to appear in the -mm kernels before 2.6.12-final is
> released.
> We'll see what happens with the upcoming changes. Maybe
> you'll be able to
> test them for me?
Basically, yes (as long as our company doesn't decide to stop the
linux experiments).
However, I depend on Ingo's RT patch, which is against the -rc series,
not against the -mm series. So I will probably not be able to apply
patches created against -mm.
--
Klaus Kusche
Entwicklung Software - Steuerung
Software Development - Control
KEBA AG
A-4041 Linz
Gewerbepark Urfahr
Tel +43 / 732 / 7090-3120
Fax +43 / 732 / 7090-8919
E-Mail: [email protected]
http://www.keba.com
> > Even when the errors described in my previous mail does not occur,
> > massive USB stick transfers cause latencies of 1 to 2 milliseconds,
> > which is way too much for realtime control systems.
>
> do these occur under PREEMPT_RT? If yes, do you get any
> useful trace if
> you enable all the tracing options but keep wakeup-timing off:
>
> # CONFIG_WAKEUP_TIMING is not set
> CONFIG_PREEMPT_TRACE=y
> CONFIG_CRITICAL_PREEMPT_TIMING=y
> CONFIG_CRITICAL_IRQSOFF_TIMING=y
> CONFIG_CRITICAL_TIMING=y
> CONFIG_LATENCY_TIMING=y
> CONFIG_LATENCY_TRACE=y
> CONFIG_MCOUNT=y
>
> this should catch any type of preempt-off section, irqs-off and
> preempt_disable() alike. (unless the tracer has a bug.)
I tried with the trace settings above, but I didn't have good luck:
1.) Tracing slows things down *a lot* (even *before* turned on):
* My own rtc test program causes 97 % CPU load when tracing is on.
On an RT kernel with tracing off, it consumes just below 20 %,
on the standard kernel, it consumes less than 3 %.
* With -f 8192, rtc_wakeup does not even start:
It blocks the whole system for about 1 minute at
"setting up consumer thread".
After that, it starts running and produces output, but ends with
"ringbuffer full" almost immediately.
Surprisingly, when started under the control of "strace", it runs,
but reports tons of missed interrupts.
With "-f 1024", it works.
2.) Tracing still doesn't seem to catch everything:
rtc_wakeup sometimes reported a max. jitter of several milliseconds,
but the max trace from /proc/latency_trace showed around 50
microseconds...
3.) However, I got some interesting traces later (see below).
They seem to be related to USB read load.
4.) When running rtc_wakeup at low rtpri (e.g. 2(12)),
I can still generate very bad "missed interrupts" counts
(even on a kernel *without* latency tracing):
core dumps: Up to 10 missed interrupts, almost continuously
USB reads: Also up to 10 missed interrupts, almost continuously
USB reads, mmap load in parallel: Up to 50, almost continuously
OOM: Up to 500
CF reads: Up to 600
Moreover, rtc_wakeup shows jitter up to 2500 microseconds
Even if there is no special test load running,
rtc_wakeup now and then misses an interrupt!
All the load is generated at shell priority, not at rt priority!
(so, ideally, it should not influence rt threads *at all*)
5.) I still do not understand the effect of "chrt"-ing "IRQ 8" to 95:
"IRQ 8" is at 49 per default, and there is no process with rtpri>49
(except for rtc_wakeup itself).
Hence, to my understanding, there should not be *any* difference
between running "IRQ 8" at 49 or 95!
However, when "IRQ 8" is at 95, a dd from the CF card doesn't hurt much.
When "IRQ 8" is at 49, the dd causes jitter of several milliseconds!
(both measured with rtc_wakeup at 89(99)).
Why? "IRQ 14" (IDE) is at 47! There is nothing except rtc_wakeup
which could block or preempt the RTC "IRQ 8"?
preemption latency trace v1.1.4 on 2.6.12-rc1-RT-V0.7.42-08
--------------------------------------------------------------------
latency: 833 us, #7/7, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: IRQ 7-724 (uid:0 nice:-5 policy:1 rt_prio:46)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
IRQ 7-724 0d... 0us : do_hardirq (do_irqd)
IRQ 7-724 0d..1 0us : note_interrupt (do_hardirq)
IRQ 7-724 0d..1 1us : end_8259A_irq (do_hardirq)
IRQ 7-724 0d..1 1us!: enable_8259A_irq (do_hardirq)
IRQ 7-724 0d... 832us : do_hardirq (do_irqd)
IRQ 7-724 0d... 833us : trace_irqs_on (do_hardirq)
Some more of those:
preemption latency trace v1.1.4 on 2.6.12-rc1-RT-V0.7.42-08
--------------------------------------------------------------------
latency: 675 us, #47/47, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: ksoftirqd/0-2 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
mmap-1000 0d... 0us : common_interrupt ((0))
mmap-1000 0d.h. 0us : do_IRQ (c028e90e 0 0)
mmap-1000 0d.h1 1us+: mask_and_ack_8259A (__do_IRQ)
mmap-1000 0d.h1 5us : redirect_hardirq (__do_IRQ)
mmap-1000 0d.h. 5us : handle_IRQ_event (__do_IRQ)
mmap-1000 0d.h. 6us : timer_interrupt (handle_IRQ_event)
mmap-1000 0d.h1 6us+: mark_offset_tsc (timer_interrupt)
mmap-1000 0d.h1 14us : do_timer (timer_interrupt)
mmap-1000 0d.h1 14us : update_process_times (timer_interrupt)
mmap-1000 0d.h1 15us : account_system_time (update_process_times)
mmap-1000 0d.h1 15us : update_mem_hiwater (update_process_times)
mmap-1000 0d.h1 16us : run_local_timers (update_process_times)
mmap-1000 0d.h1 17us : raise_softirq (update_process_times)
mmap-1000 0d.h1 18us : scheduler_tick (timer_interrupt)
mmap-1000 0d.h1 18us : sched_clock (scheduler_tick)
mmap-1000 0d.h1 20us : profile_hit (timer_interrupt)
mmap-1000 0d.h1 20us : note_interrupt (__do_IRQ)
mmap-1000 0d.h1 21us : end_8259A_irq (__do_IRQ)
mmap-1000 0d.h1 22us!: enable_8259A_irq (__do_IRQ)
mmap-1000 0d.h. 662us : irq_exit (do_IRQ)
mmap-1000 0d..1 662us : do_softirq (irq_exit)
mmap-1000 0d..1 663us : __do_softirq (do_softirq)
mmap-1000 0d..1 663us : wake_up_process (do_softirq)
mmap-1000 0d..1 664us : try_to_wake_up (wake_up_process)
mmap-1000 0d..2 664us : activate_task (try_to_wake_up)
mmap-1000 0d..2 664us : sched_clock (activate_task)
mmap-1000 0d..2 665us : recalc_task_prio (activate_task)
mmap-1000 0d..2 665us : effective_prio (recalc_task_prio)
mmap-1000 0d..2 665us : activate_task <<...>-2> (69 1):
mmap-1000 0d..2 666us : enqueue_task (activate_task)
mmap-1000 0dn.2 666us : try_to_wake_up <<...>-2> (69 76):
mmap-1000 0dn.1 667us : preempt_schedule (try_to_wake_up)
mmap-1000 0dn.1 667us : wake_up_process (do_softirq)
mmap-1000 0dn.. 668us : preempt_schedule_irq (need_resched)
mmap-1000 0dn.. 668us : __schedule (preempt_schedule_irq)
mmap-1000 0dn.. 668us : profile_hit (__schedule)
mmap-1000 0dn.1 669us : sched_clock (__schedule)
mmap-1000 0dn.2 670us : dequeue_task (__schedule)
mmap-1000 0dn.2 671us : recalc_task_prio (__schedule)
mmap-1000 0dn.2 671us : effective_prio (recalc_task_prio)
mmap-1000 0dn.2 671us : enqueue_task (__schedule)
<...>-2 0d..2 672us : __switch_to (__schedule)
<...>-2 0d..2 673us : __schedule <mmap-1000> (76 69):
<...>-2 0d... 674us : schedule (ksoftirqd)
<...>-2 0d... 674us : trace_irqs_on (schedule)
preemption latency trace v1.1.4 on 2.6.12-rc1-RT-V0.7.42-08
--------------------------------------------------------------------
latency: 951 us, #27/27, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: IRQ 7-724 (uid:0 nice:-5 policy:1 rt_prio:46)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
mmap-1000 0d... 0us : common_interrupt ((0))
mmap-1000 0d.h. 0us : do_IRQ (c012d6d5 7 0)
mmap-1000 0d.h1 2us!: mask_and_ack_8259A (__do_IRQ)
mmap-1000 0d.h1 938us : redirect_hardirq (__do_IRQ)
mmap-1000 0d.h1 939us : wake_up_process (redirect_hardirq)
mmap-1000 0d.h1 939us : try_to_wake_up (wake_up_process)
mmap-1000 0d.h2 940us : activate_task (try_to_wake_up)
mmap-1000 0d.h2 940us : sched_clock (activate_task)
mmap-1000 0d.h2 941us : recalc_task_prio (activate_task)
mmap-1000 0d.h2 941us : effective_prio (recalc_task_prio)
mmap-1000 0d.h2 942us : activate_task <<...>-724> (35 1):
mmap-1000 0d.h2 942us : enqueue_task (activate_task)
mmap-1000 0dnh2 943us : try_to_wake_up <<...>-724> (35 7d):
mmap-1000 0dnh1 943us : preempt_schedule (try_to_wake_up)
mmap-1000 0dnh1 944us : wake_up_process (redirect_hardirq)
mmap-1000 0dnh. 944us : preempt_schedule (__do_IRQ)
mmap-1000 0dnh. 945us : irq_exit (do_IRQ)
mmap-1000 0dn.. 945us : preempt_schedule_irq (need_resched)
mmap-1000 0dn.. 945us : __schedule (preempt_schedule_irq)
mmap-1000 0dn.. 946us : profile_hit (__schedule)
mmap-1000 0dn.1 946us : sched_clock (__schedule)
<...>-724 0d..2 948us : __switch_to (__schedule)
<...>-724 0d..2 949us : __schedule <mmap-1000> (7d 35):
<...>-724 0d... 950us : schedule (do_irqd)
<...>-724 0d... 950us : trace_irqs_on (schedule)
preemption latency trace v1.1.4 on 2.6.12-rc1-RT-V0.7.42-08
--------------------------------------------------------------------
latency: 985 us, #76/76, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: ksoftirqd/0-2 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
ksoftirq-2 0...1 0us : ksoftirqd (kthread)
ksoftirq-2 0d.h1 1us : do_IRQ (c01306da 7 0)
ksoftirq-2 0d.h2 2us!: mask_and_ack_8259A (__do_IRQ)
ksoftirq-2 0d.h2 944us : redirect_hardirq (__do_IRQ)
ksoftirq-2 0d.h2 944us : wake_up_process (redirect_hardirq)
ksoftirq-2 0d.h2 944us : try_to_wake_up (wake_up_process)
ksoftirq-2 0d.h3 945us : activate_task (try_to_wake_up)
ksoftirq-2 0d.h3 945us : sched_clock (activate_task)
ksoftirq-2 0d.h3 946us : recalc_task_prio (activate_task)
ksoftirq-2 0d.h3 946us : effective_prio (recalc_task_prio)
ksoftirq-2 0d.h3 947us : activate_task <<...>-724> (35 3):
ksoftirq-2 0d.h3 947us : enqueue_task (activate_task)
ksoftirq-2 0dnh3 948us : try_to_wake_up <<...>-724> (35 6a):
ksoftirq-2 0dnh2 948us : preempt_schedule (try_to_wake_up)
ksoftirq-2 0dnh2 948us : wake_up_process (redirect_hardirq)
ksoftirq-2 0dnh1 949us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh1 949us : irq_exit (do_IRQ)
ksoftirq-2 0dn.1 950us < (608)
ksoftirq-2 0dnh1 951us : do_IRQ (c01306da 0 0)
ksoftirq-2 0dnh2 952us : mask_and_ack_8259A (__do_IRQ)
ksoftirq-2 0dnh2 953us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh2 954us : redirect_hardirq (__do_IRQ)
ksoftirq-2 0dnh1 954us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh1 955us : handle_IRQ_event (__do_IRQ)
ksoftirq-2 0dnh1 955us : timer_interrupt (handle_IRQ_event)
ksoftirq-2 0dnh2 956us+: mark_offset_tsc (timer_interrupt)
ksoftirq-2 0dnh3 959us : preempt_schedule (mark_offset_tsc)
ksoftirq-2 0dnh2 960us : preempt_schedule (mark_offset_tsc)
ksoftirq-2 0dnh2 960us : preempt_schedule (mark_offset_tsc)
ksoftirq-2 0dnh2 961us : do_timer (timer_interrupt)
ksoftirq-2 0dnh2 961us : update_process_times (timer_interrupt)
ksoftirq-2 0dnh2 961us : account_system_time (update_process_times)
ksoftirq-2 0dnh2 962us : update_mem_hiwater (update_process_times)
ksoftirq-2 0dnh2 962us : run_local_timers (update_process_times)
ksoftirq-2 0dnh2 962us : raise_softirq (update_process_times)
ksoftirq-2 0dnh2 963us : scheduler_tick (timer_interrupt)
ksoftirq-2 0dnh2 964us : sched_clock (scheduler_tick)
ksoftirq-2 0dnh2 965us : preempt_schedule (scheduler_tick)
ksoftirq-2 0dnh2 966us : profile_hit (timer_interrupt)
ksoftirq-2 0dnh1 966us : preempt_schedule (timer_interrupt)
ksoftirq-2 0dnh2 967us : note_interrupt (__do_IRQ)
ksoftirq-2 0dnh2 967us : end_8259A_irq (__do_IRQ)
ksoftirq-2 0dnh2 968us : enable_8259A_irq (__do_IRQ)
ksoftirq-2 0dnh2 969us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh1 969us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh1 970us : irq_exit (do_IRQ)
ksoftirq-2 0dn.2 970us : do_softirq (irq_exit)
ksoftirq-2 0dn.2 970us : __do_softirq (do_softirq)
ksoftirq-2 0dn.2 971us : wake_up_process (do_softirq)
ksoftirq-2 0dn.2 971us : try_to_wake_up (wake_up_process)
ksoftirq-2 0dn.2 972us : preempt_schedule (try_to_wake_up)
ksoftirq-2 0dn.2 972us : wake_up_process (do_softirq)
ksoftirq-2 0dn.1 973us < (608)
ksoftirq-2 0dnh1 974us : do_IRQ (c01306da 8 0)
ksoftirq-2 0dnh2 975us+: mask_and_ack_8259A (__do_IRQ)
ksoftirq-2 0dnh2 978us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh2 978us : redirect_hardirq (__do_IRQ)
ksoftirq-2 0dnh2 979us : wake_up_process (redirect_hardirq)
ksoftirq-2 0dnh2 979us : try_to_wake_up (wake_up_process)
ksoftirq-2 0dnh3 979us : activate_task (try_to_wake_up)
ksoftirq-2 0dnh3 979us : sched_clock (activate_task)
ksoftirq-2 0dnh3 980us : recalc_task_prio (activate_task)
ksoftirq-2 0dnh3 980us : effective_prio (recalc_task_prio)
ksoftirq-2 0dnh3 981us : activate_task <<...>-664> (4 4):
ksoftirq-2 0dnh3 981us : enqueue_task (activate_task)
ksoftirq-2 0dnh3 981us : try_to_wake_up <<...>-664> (4 6a):
ksoftirq-2 0dnh2 982us : preempt_schedule (try_to_wake_up)
ksoftirq-2 0dnh2 982us : wake_up_process (redirect_hardirq)
ksoftirq-2 0dnh1 982us : preempt_schedule (__do_IRQ)
ksoftirq-2 0dnh1 983us : irq_exit (do_IRQ)
ksoftirq-2 0dn.2 983us : do_softirq (irq_exit)
ksoftirq-2 0dn.2 983us : __do_softirq (do_softirq)
ksoftirq-2 0dn.1 984us < (608)
ksoftirq-2 0.n.1 984us : ksoftirqd (kthread)
ksoftirq-2 0.n.1 985us : sub_preempt_count (ksoftirqd)
--
Klaus Kusche (Software Development - Control Systems)
KEBA AG Gewerbepark Urfahr, A-4041 Linz, Austria (Europe)
Tel: +43 / 732 / 7090-3120 Fax: +43 / 732 / 7090-8919
E-Mail: [email protected] WWW: http://www.keba.com
* kus Kusche Klaus <[email protected]> wrote:
> IRQ 7-724 0d..1 1us : end_8259A_irq (do_hardirq)
> IRQ 7-724 0d..1 1us!: enable_8259A_irq (do_hardirq)
> IRQ 7-724 0d... 832us : do_hardirq (do_irqd)
> IRQ 7-724 0d... 833us : trace_irqs_on (do_hardirq)
> mmap-1000 0d.h1 21us : end_8259A_irq (__do_IRQ)
> mmap-1000 0d.h1 22us!: enable_8259A_irq (__do_IRQ)
> mmap-1000 0d.h. 662us : irq_exit (do_IRQ)
> mmap-1000 0d..1 662us : do_softirq (irq_exit)
> mmap-1000 0d.h. 0us : do_IRQ (c012d6d5 7 0)
> mmap-1000 0d.h1 2us!: mask_and_ack_8259A (__do_IRQ)
> mmap-1000 0d.h1 938us : redirect_hardirq (__do_IRQ)
> mmap-1000 0d.h1 939us : wake_up_process (redirect_hardirq)
such 'freezes' almost certainly signal some sort of hardware latency -
some device holding the system bus up during DMA. There is no
algorithmic reason for any of those steps above to take several hundreds
of microseconds.
Ingo
On Fri, 1 Apr 2005, kus Kusche Klaus wrote:
> > The biggest advantage would come from using a bottom-half
> > handler to do
> > most of the work. Right now the uhci-hcd driver does
> > everything in its
> > interrupt handler. This would certainly help IRQ latency; it
> > might not
> > affect application latency very much.
>
> Sounds very reasonable, thanks. Also helps application latency,
> because with the RT patches, I can tune the rt prio of softirq
> execution (that's where bottom-half goes, doesn't it?) w.r.t. the
> rt prio of the application threads.
Yes. Bear in mind, however, that if these application threads are doing
I/O over USB then they will be forced to wait for the bottom half to
execute, regardless of its priority.
> However, if I understand things correctly, if you really need
> to disable all interrupts while doing the USB work, it will not
> make any difference if IRQs are disabled while you are in the
> USB IRQ handler, or if they are disabled for the same amount of
> work/time in the bottom-half code.
For most of the USB work it will be necessary only to insure that no more
than one copy of the bottom-half handler is running at a time, which I
think the kernel does automatically for tasklets. There are a few places
where all IRQs will have to be disabled, but those places are relatively
small and short.
Right now, of course, everything runs with IRQs disabled.
> > We'll see what happens with the upcoming changes. Maybe
> > you'll be able to
> > test them for me?
>
> Basically, yes (as long as our company doesn't decide to stop the
> linux experiments).
>
> However, I depend on Ingo's RT patch, which is against the -rc series,
> not against the -mm series. So I will probably not be able to apply
> patches created against -mm.
Okay. It will be a while before the new code is ready and the changes on
which it depends have gotten into -rc.
Alan Stern
> * kus Kusche Klaus <[email protected]> wrote:
> > IRQ 7-724 0d..1 1us : end_8259A_irq (do_hardirq)
> > IRQ 7-724 0d..1 1us!: enable_8259A_irq (do_hardirq)
> > IRQ 7-724 0d... 832us : do_hardirq (do_irqd)
> > IRQ 7-724 0d... 833us : trace_irqs_on (do_hardirq)
>
> > mmap-1000 0d.h1 21us : end_8259A_irq (__do_IRQ)
> > mmap-1000 0d.h1 22us!: enable_8259A_irq (__do_IRQ)
> > mmap-1000 0d.h. 662us : irq_exit (do_IRQ)
> > mmap-1000 0d..1 662us : do_softirq (irq_exit)
>
> > mmap-1000 0d.h. 0us : do_IRQ (c012d6d5 7 0)
> > mmap-1000 0d.h1 2us!: mask_and_ack_8259A (__do_IRQ)
> > mmap-1000 0d.h1 938us : redirect_hardirq (__do_IRQ)
> > mmap-1000 0d.h1 939us : wake_up_process (redirect_hardirq)
>
> such 'freezes' almost certainly signal some sort of hardware
> latency -
> some device holding the system bus up during DMA. There is no
> algorithmic reason for any of those steps above to take
> several hundreds
> of microseconds.
>
> Ingo
I asked our hardware team. The hardware has two devices which are
in use and capable of busmaster/DMA transfers:
The intel e100 ethernet controller and the intel PIIX4 USB
controller.
The IDE interface is also a busmaster, but there are only PIO IDE
devices.
I suspect the latter, as USB reads were running in parallel...
How many bytes are transferred at most by the USB controller
for a single request? How long may this take?
Any experiences / opinitions / advices?
Moreover, we know from experience that the "WBINDV" instruction
(Write back and invalidate CPU cache) can cause such latencies.
Does this instruction occur anywhere in Linux?
--
Klaus Kusche (Software Development - Control Systems)
KEBA AG Gewerbepark Urfahr, A-4041 Linz, Austria (Europe)
Tel: +43 / 732 / 7090-3120 Fax: +43 / 732 / 7090-8919
E-Mail: [email protected] WWW: http://www.keba.com
* kus Kusche Klaus <[email protected]> wrote:
> Moreover, we know from experience that the "WBINDV" instruction (Write
> back and invalidate CPU cache) can cause such latencies.
>
> Does this instruction occur anywhere in Linux?
yes, they rarely occur when MTRR's are set (and some drivers like video
uses it too), but then they'd also show up in the trace. The only other
possibility would be if a driver used wbinvd in a preemptible section -
that would not be traced. OTOH, it could still show up in wakeup-latency
tracing.
To make sure, could you remove all relevant wbinvd's from your kernel
tree? You can just comment out those lines from all relevant 'grep -rl
wbinvd . | grep -v x86_64' files. (and in assembly defines, just replace
the "wbinvd" with "nop") The kernel will most likely still work most of
the time.
Or if you want to be safe: change all wbinvd occurances to:
preempt_disable(); <wbinvd>; preempt_enable() sections, for tracing to
pick them up.
Ingo
On Mon, 4 Apr 2005, kus Kusche Klaus wrote:
> I asked our hardware team. The hardware has two devices which are
> in use and capable of busmaster/DMA transfers:
> The intel e100 ethernet controller and the intel PIIX4 USB
> controller.
> The IDE interface is also a busmaster, but there are only PIO IDE
> devices.
>
> I suspect the latter, as USB reads were running in parallel...
> How many bytes are transferred at most by the USB controller
> for a single request? How long may this take?
Your questions aren't very clear. The USB controller will do intermittent
DMA (once per millisecond) even when no USB transfers are pending, so long
as a USB device is attached. When transfers are pending it will do as
much DMA as required to complete the transfers. The amount of time
depends on the amount of data to be transferred and the speed at which the
device can provide/accept the data. For Bulk transfers the DMA activity
is more or less continual.
> Any experiences / opinitions / advices?
I've had plenty of experience using USB, but none in measuring bus
utilization. However my guess is that the controller puts a fairly large
load on the system.
Alan Stern