sys_sendto() spinning for 1.6ms

sys_sendto() spinning for 1.6ms

[David Laight]

I'm looking into unexpected delays in some real time (RTP audio) processing.
Mostly they are a few 100 usecs in the softint code.

However I've just triggered in sendto() on a raw IPV4 socket taking 1.6ms.
Most of the sends take less than 32us.
The process isn't sleeping and there are no interrupts.
Any idea where it might be spinning?

I'm running ftrace monitoring scheduler events, system calls and
interrupts (hard and soft) but can't turn on anything other than
selective function trace (the trace cost is far too high).

The ftrace at the time of the sendto() is (I'm only running 4 cpu):
    pid-28219 [002] .... 1979891.159912: sys_sendto(fd: 394, buff: 7ffbcb2e2940, len: c8, flags: 0, addr: 7ffbccdc9490, addr_len: 10)
    pid-28217 [003] .... 1979891.159912: sys_recvfrom(fd: 23c, ubuf: 7ffbcb1db100, size: 748, flags: 0, addr: 7ffbcddcb5b0, addr_len: 7ffbcddcb5ac)
    pid-28218 [001] .... 1979891.159912: sys_futex(uaddr: 113d8e0, op: 80, val: 2, utime: 0, uaddr2: 113d8e0, val3: 6e3a)
    pid-28216 [000] .... 1979891.159912: sys_futex(uaddr: 113d8e0, op: 81, val: 1, utime: 7ffbce5cc920, uaddr2: 113d8e0, val3: 6e38)
    pid-28217 [003] .... 1979891.159912: sys_recvfrom -> 0xac

Cpu 2 trace is:
    pid-28219 [002] .... 1979891.159910: sys_futex(uaddr: 113d8e0, op: 81, val: 1, utime: 7ffbccdc9920, uaddr2: 113d8e0, val3: 6e3b)
    pid-28219 [002] .... 1979891.159911: sys_futex -> 0x0
    pid-28219 [002] .... 1979891.159912: sys_sendto(fd: 394, buff: 7ffbcb2e2940, len: c8, flags: 0, addr: 7ffbccdc9490, addr_len: 10)
    pid-28219 [002] .... 1979891.161647: sys_sendto -> 0xc8
    pid-28219 [002] .... 1979891.161648: sys_pread64(fd: 3ae, buf: 7ffbccdc9420, count: 1, pos: 0)
    pid-28219 [002] .... 1979891.161650: sys_pread64 -> 0x1
    pid-28219 [002] .... 1979891.161651: sys_pwrite64(fd: 3ae, buf: d495e8, count: 1, pos: 0)

The previous send on fd 394 was much earlier and that socket is only used
by that process, and only for sends (to avoid sleeping on the socket lock).

It can't be an problem with the socket send buffer - because that would sleep.

The other 3 cpu carry on processing (the futex calls return immediately).
In fact they all sleep 1.4ms before the sento() finishes.

At the moment the trace is a sample of 1 - so I don't know if the concurrent
sento() and recvfrom() are significant.
They will both be the same remote IP, and might be the same port.

Ideas before I start trying to bisect the call graph?

A rough histogram of the time (ns) for the sendto() call.
0k: 71866866
48k: 99213
80k: 3583
112k: 371
144k: 245
176k: 694
208k: 382
240k: 214
272k: 20
304k: 13
336k: 15
368k: 13
400k: 11
432k: 14
464k: 12
496k: 7
528k: 10
560k: 2
592k: 1
624k: 2
656k: 1
688k: 0 (twice)
752k: 1
784k: 0 (twice)
848k: 1
880k: 1
912k: 0 (24 times)
1680k: 1

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)

RE: sys_sendto() spinning for 1.6ms

[David Laight]

From: David Laight
> Sent: 27 February 2020 13:19
> 
> I'm looking into unexpected delays in some real time (RTP audio) processing.
> Mostly they are a few 100 usecs in the softint code.
> 
> However I've just triggered in sendto() on a raw IPV4 socket taking 1.6ms.
> Most of the sends take less than 32us.
...
> Cpu 2 trace is:
>     pid-28219 [002] .... 1979891.159912: sys_sendto(fd: 394, buff: 7ffbcb2e2940, len: c8, flags: 0,
> addr: 7ffbccdc9490, addr_len: 10)
>     pid-28219 [002] .... 1979891.161647: sys_sendto -> 0xc8
> 

Ok, I've found the buggy piece of crap responsible:

1992857.294910 |   2)  Prosody-5812  |               |  raw_sendmsg() {
1992857.294912 |   2)  Prosody-5812  |   1.099 us    |    __ew32_prepare [e1000e]();
1992857.294913 |   2)  Prosody-5812  |   0.855 us    |    __ew32_prepare [e1000e]();
1992857.294915 |   2)  Prosody-5812  |   0.773 us    |    __ew32_prepare [e1000e]();
1992857.294916 |   2)  Prosody-5812  | ! 202.689 us  |    __ew32_prepare [e1000e]();
1992857.295155 |   2)  Prosody-5812  | ! 253.162 us  |    __ew32_prepare [e1000e]();
1992857.295409 |   2)  Prosody-5812  |   0.855 us    |    __ew32_prepare [e1000e]();
1992857.295411 |   2)  Prosody-5812  | ! 500.828 us  |  }

/**
 * __ew32_prepare - prepare to write to MAC CSR register on certain parts
 * @hw: pointer to the HW structure
 *
 * When updating the MAC CSR registers, the Manageability Engine (ME) could
 * be accessing the registers at the same time.  Normally, this is handled in
 * h/w by an arbiter but on some parts there is a bug that acknowledges Host
 * accesses later than it should which could result in the register to have
 * an incorrect value.  Workaround this by checking the FWSM register which
 * has bit 24 set while ME is accessing MAC CSR registers, wait if it is set
 * and try again a number of times.
 **/
s32 __ew32_prepare(struct e1000_hw *hw)
{
        s32 i = E1000_ICH_FWSM_PCIM2PCI_COUNT; // 2000

        while ((er32(FWSM) & E1000_ICH_FWSM_PCIM2PCI) && --i)
                udelay(50);

        return i;
}

WTF!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

That it just so broken....

Notwithstanding anything else the bit can get set just after
we've checked it isn't set.
So the code doesn't solve anything at all.

	David

-
Registered Address Lakeside, Bramley Road, Mount Farm, Milton Keynes, MK1 1PT, UK
Registration No: 1397386 (Wales)