Re: locking changes in tty broke low latency feature

From: Peter Hurley
Date: Thu Feb 20 2014 - 13:16:53 EST


On 02/19/2014 09:55 PM, Peter Hurley wrote:
On 02/19/2014 06:06 PM, Hal Murray wrote:
Can you give me an idea of your device's average and minimum required
latency (please be specific)? Is your target arch x86 [so I can evaluate the
the impact of bus-locked instructions relative to your expected]?

The code I'm familiar with is ntpd and gpsd. They run on almost any hardware
or OS and talk to a wide collection of devices.

There is no hard requirement for latency. They just work better with lower
latency. The lower the better.

People gripe about the latency due to USB polling which is about a ms.

Have you tried 3.12+ without low_latency? I ripped out a lot of locks
from 3.12+ so it's possible it already meets your requirements.

Using Alan's idea to mock up a latency test, I threw together a test jig
using two computers running 3.14-rc1 and my fwserial driver (modified to
not aggregrate writes) in raw mode where the target does this:

while (1) {
read 64 bytes
compare to pattern
write 1 byte response
}

and the sender does this:

for (i = 0; i < 2000; i++) {
write 64-byte pattern
read 1 byte response
}

Sender completes 2000 loops in 160ms total run time;
that's 80us average per complete round-trip.

Here's a snapshot of a function trace for 1 complete round trip at the target:

<idle>-0 [007] d.h1 4856.935561: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000010 AR_req
<idle>-0 [007] ..s1 4856.935566: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AR spd 2 tl 2a, ffc1 -> ffc0, ack_complete, BW req, 800000000004 40,0
<idle>-0 [007] ..s1 4856.935567: tty_flip_buffer_push <-fwtty_port_handler
kworker/7:0-6872 [007] .... 4856.935571: flush_to_ldisc <-process_one_work
tty-latency-tes-6891 [003] .... 4856.935578: n_tty_write <-tty_write
<idle>-0 [003] d.h1 4856.935591: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000001 AT_req
<idle>-0 [003] ..s1 4856.935594: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AT spd 2 tl 12, ffc0 -> ffc1, ack_complete, BW req, 800000000004 1,0

The same snapshot explained:

The firewire controller IRQ for received packet in rx dma fifo:

<idle>-0 [007] d.h1 4856.935561: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000010 AR_req

The firewire-ohci driver rx fifo tasklet running:

<idle>-0 [007] ..s1 4856.935566: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AR spd 2 tl 2a, ffc1 -> ffc0, ack_complete, BW req, 800000000004 40,0

The fwserial driver schdeduling the rx data:

<idle>-0 [007] ..s1 4856.935567: tty_flip_buffer_push <-fwtty_port_handler

The tty buffer input worker running:

kworker/7:0-6872 [007] .... 4856.935571: flush_to_ldisc <-process_one_work

The test application having received the data, compared it,
and writing the 1-byte response:

tty-latency-tes-6891 [003] .... 4856.935578: n_tty_write <-tty_write

The firewire controller IRQ for running the tx dma fifo:

<idle>-0 [003] d.h1 4856.935591: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000001 AT_req

The firewire-ohci driver tx fifo tasklet acknowledging the sender
of the 64-byte packet has received the 1-byte response:

<idle>-0 [003] ..s1 4856.935594: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AT spd 2 tl 12, ffc0 -> ffc1, ack_complete, BW req, 800000000004 1,0


... trace continued for another 4x 64-byte reads and 1 byte responses:

<idle>-0 [007] d.h1 4856.935646: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000010 AR_req
<idle>-0 [007] ..s1 4856.935650: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AR spd 2 tl 2b, ffc1 -> ffc0, ack_complete, BW req, 800000000004 40,0
<idle>-0 [007] ..s1 4856.935651: tty_flip_buffer_push <-fwtty_port_handler
kworker/7:0-6872 [007] .... 4856.935655: flush_to_ldisc <-process_one_work
tty-latency-tes-6891 [003] .... 4856.935662: n_tty_write <-tty_write
<idle>-0 [003] d.h1 4856.935674: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000001 AT_req
<idle>-0 [003] ..s1 4856.935678: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AT spd 2 tl 13, ffc0 -> ffc1, ack_complete, BW req, 800000000004 1,0
<idle>-0 [007] d.h1 4856.935729: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000010 AR_req
<idle>-0 [007] ..s1 4856.935733: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AR spd 2 tl 2c, ffc1 -> ffc0, ack_complete, BW req, 800000000004 40,0
<idle>-0 [007] ..s1 4856.935734: tty_flip_buffer_push <-fwtty_port_handler
kworker/7:0-6872 [007] .... 4856.935738: flush_to_ldisc <-process_one_work
tty-latency-tes-6891 [003] .... 4856.935746: n_tty_write <-tty_write
<idle>-0 [003] d.h1 4856.935758: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000001 AT_req
<idle>-0 [003] ..s1 4856.935762: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AT spd 2 tl 14, ffc0 -> ffc1, ack_complete, BW req, 800000000004 1,0
<idle>-0 [007] d.h1 4856.935812: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000010 AR_req
<idle>-0 [007] ..s1 4856.935816: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AR spd 2 tl 2d, ffc1 -> ffc0, ack_complete, BW req, 800000000004 40,0
<idle>-0 [007] ..s1 4856.935817: tty_flip_buffer_push <-fwtty_port_handler
kworker/7:0-6872 [007] .... 4856.935821: flush_to_ldisc <-process_one_work
tty-latency-tes-6891 [003] .... 4856.935828: n_tty_write <-tty_write
<idle>-0 [003] d.h1 4856.935844: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000001 AT_req
<idle>-0 [003] ..s1 4856.935847: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AT spd 2 tl 15, ffc0 -> ffc1, ack_complete, BW req, 800000000004 1,0
<idle>-0 [007] d.h1 4856.935895: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000010 AR_req
<idle>-0 [007] ..s1 4856.935899: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AR spd 2 tl 2e, ffc1 -> ffc0, ack_complete, BW req, 800000000004 40,0
<idle>-0 [007] ..s1 4856.935900: tty_flip_buffer_push <-fwtty_port_handler
kworker/7:0-6872 [007] .... 4856.935904: flush_to_ldisc <-process_one_work
tty-latency-tes-6891 [003] .... 4856.935911: n_tty_write <-tty_write
<idle>-0 [003] d.h1 4856.935923: irq_handler: firewire_ohci 0000:07:06.0: IRQ 00000001 AT_req
<idle>-0 [003] ..s1 4856.935927: log_ar_at_event.isra.33: firewire_ohci 0000:07:06.0: AT spd 2 tl 16, ffc0 -> ffc1, ack_complete, BW req, 800000000004 1,0


I think this shows that low_latency is unnecessary and should
just be removed/ignored by the tty core.

Let me know if you want my test jig (or fwserial patch). The test
was run on a 10-year old Vaio single-core laptop as the sender and
6-year old dual socket xeon workstation (so nothing super tricked
out for this test).


Regards,
Peter Hurley
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/