public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed
* 2.6.11, USB: High latency?
@ 2005-03-30 13:51 kus Kusche Klaus
  2005-03-30 15:55 ` Alan Stern
  2005-03-31 11:30 ` Ingo Molnar
  0 siblings, 2 replies; 25+ messages in thread
From: kus Kusche Klaus @ 2005-03-30 13:51 UTC (permalink / raw)
  To: stern, linux-usb-users, linux-kernel

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: kus@keba.com
> www.keba.com
> 
> 

^ permalink raw reply	[flat|nested] 25+ messages in thread
* Re: 2.6.11, USB: High latency?
@ 2005-03-30 22:57 David Brownell
  2005-03-31  0:43 ` Lee Revell
  2005-03-31  0:51 ` Lee Revell
  0 siblings, 2 replies; 25+ messages in thread
From: David Brownell @ 2005-03-30 22:57 UTC (permalink / raw)
  To: linux-kernel

Quoth kus@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. 

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 rlevell@joe-job.com:
> 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

^ permalink raw reply	[flat|nested] 25+ messages in thread
* RE: 2.6.11, USB: High latency?
@ 2005-03-31 11:15 kus Kusche Klaus
  2005-03-31 16:48 ` Alan Stern
  0 siblings, 1 reply; 25+ messages in thread
From: kus Kusche Klaus @ 2005-03-31 11:15 UTC (permalink / raw)
  To: Alan Stern; +Cc: linux-usb-users, linux-kernel

> 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: kus@keba.com
www.keba.com
 

^ permalink raw reply	[flat|nested] 25+ messages in thread
* RE: 2.6.11, USB: High latency?
@ 2005-03-31 12:12 kus Kusche Klaus
  0 siblings, 0 replies; 25+ messages in thread
From: kus Kusche Klaus @ 2005-03-31 12:12 UTC (permalink / raw)
  To: David Brownell, linux-kernel

> 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: kus@keba.com
www.keba.com

^ permalink raw reply	[flat|nested] 25+ messages in thread
* RE: 2.6.11, USB: High latency?
@ 2005-04-01  6:46 kus Kusche Klaus
  2005-04-01 17:20 ` Alan Stern
  0 siblings, 1 reply; 25+ messages in thread
From: kus Kusche Klaus @ 2005-04-01  6:46 UTC (permalink / raw)
  To: Alan Stern; +Cc: linux-usb-users, linux-kernel

> > > 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: kus@keba.com
www.keba.com

^ permalink raw reply	[flat|nested] 25+ messages in thread
* RE: 2.6.11, USB: High latency?
@ 2005-04-01 13:16 kus Kusche Klaus
  2005-04-01 13:41 ` Ingo Molnar
  0 siblings, 1 reply; 25+ messages in thread
From: kus Kusche Klaus @ 2005-04-01 13:16 UTC (permalink / raw)
  To: Ingo Molnar, kus Kusche Klaus; +Cc: stern, linux-usb-users, linux-kernel

> > 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: kus@keba.com                                WWW: www.keba.com

^ permalink raw reply	[flat|nested] 25+ messages in thread
* RE: 2.6.11, USB: High latency?
@ 2005-04-04  8:03 kus Kusche Klaus
  2005-04-04  8:36 ` Ingo Molnar
  2005-04-04 19:40 ` Alan Stern
  0 siblings, 2 replies; 25+ messages in thread
From: kus Kusche Klaus @ 2005-04-04  8:03 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: stern, linux-usb-users, linux-kernel

> * kus Kusche Klaus <kus@keba.com> 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: kus@keba.com                                WWW: www.keba.com

^ permalink raw reply	[flat|nested] 25+ messages in thread

end of thread, other threads:[~2005-04-04 19:41 UTC | newest]

Thread overview: 25+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2005-03-30 13:51 2.6.11, USB: High latency? kus Kusche Klaus
2005-03-30 15:55 ` Alan Stern
2005-03-30 21:28   ` Lee Revell
2005-03-31 11:30 ` Ingo Molnar
  -- strict thread matches above, loose matches on Subject: below --
2005-03-30 22:57 David Brownell
2005-03-31  0:43 ` Lee Revell
2005-03-31  1:13   ` David Brownell
2005-03-31  1:21     ` Lee Revell
2005-03-31  1:32       ` David Brownell
2005-03-31  0:51 ` Lee Revell
2005-03-31  1:28   ` David Brownell
2005-03-31  1:32     ` Lee Revell
2005-03-31  1:40       ` David Brownell
2005-03-31  1:44         ` Lee Revell
2005-03-31  1:39     ` Lee Revell
2005-03-31 11:15 kus Kusche Klaus
2005-03-31 16:48 ` Alan Stern
2005-03-31 12:12 kus Kusche Klaus
2005-04-01  6:46 kus Kusche Klaus
2005-04-01 17:20 ` Alan Stern
2005-04-01 13:16 kus Kusche Klaus
2005-04-01 13:41 ` Ingo Molnar
2005-04-04  8:03 kus Kusche Klaus
2005-04-04  8:36 ` Ingo Molnar
2005-04-04 19:40 ` Alan Stern

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox