Re: epoll_wait() performance

From: Jesper Dangaard Brouer
Date: Thu Nov 28 2019 - 06:12:24 EST

On Wed, 27 Nov 2019 16:04:12 +0000
David Laight <David.Laight@xxxxxxxxxx> wrote:

> From: Jesper Dangaard Brouer
> > Sent: 27 November 2019 15:48
> > On Wed, 27 Nov 2019 10:39:44 +0000 David Laight <David.Laight@xxxxxxxxxx> wrote:
> >
> > > ...
> > > > > While using recvmmsg() to read multiple messages might seem a good idea, it is much
> > > > > slower than recv() when there is only one message (even recvmsg() is a lot slower).
> > > > > (I'm not sure why the code paths are so slow, I suspect it is all the copy_from_user()
> > > > > and faffing with the user iov[].)
> > > > >
> > > > > So using poll() we repoll the fd after calling recv() to find is there is a second message.
> > > > > However the second poll has a significant performance cost (but less than using recvmmsg()).
> > > >
> > > > That sounds wrong. Single recvmmsg(), even when receiving only a
> > > > single message, should be faster than two syscalls - recv() and
> > > > poll().
> > >
> > > My suspicion is the extra two copy_from_user() needed for each recvmsg are a
> > > significant overhead, most likely due to the crappy code that tries to stop
> > > the kernel buffer being overrun.
> > >
> > > I need to run the tests on a system with a 'home built' kernel to see how much
> > > difference this make (by seeing how much slower duplicating the copy makes it).
> > >
> > > The system call cost of poll() gets factored over a reasonable number of sockets.
> > > So doing poll() on a socket with no data is a lot faster that the setup for recvmsg
> > > even allowing for looking up the fd.
> > >
> > > This could be fixed by an extra flag to recvmmsg() to indicate that you only really
> > > expect one message and to call the poll() function before each subsequent receive.
> > >
> > > There is also the 'reschedule' that Eric added to the loop in recvmmsg.
> > > I don't know how much that actually costs.
> > > In this case the process is likely to be running at a RT priority and pinned to a cpu.
> > > In some cases the cpu is also reserved (at boot time) so that 'random' other code can't use it.
> > >
> > > We really do want to receive all these UDP packets in a timely manner.
> > > Although very low latency isn't itself an issue.
> > > The data is telephony audio with (typically) one packet every 20ms.
> > > The code only looks for packets every 10ms - that helps no end since, in principle,
> > > only a single poll()/epoll_wait() call (on all the sockets) is needed every 10ms.
> >
> > I have a simple udp_sink tool[1] that cycle through the different
> > receive socket system calls. I gave it a quick spin on a F31 kernel
> > 5.3.12-300.fc31.x86_64 on a mlx5 100G interface, and I'm very surprised
> > to see a significant regression/slowdown for recvMmsg.
> >
> > $ sudo ./udp_sink --port 9 --repeat 1 --count $((10**7))
> > run count ns/pkt pps cycles payload
> > recvMmsg/32 run: 0 10000000 1461.41 684270.96 5261 18 demux:1
> > recvmsg run: 0 10000000 889.82 1123824.84 3203 18 demux:1
> > read run: 0 10000000 974.81 1025841.68 3509 18 demux:1
> > recvfrom run: 0 10000000 1056.51 946513.44 3803 18 demux:1
> >
> > Normal recvmsg almost have double performance that recvmmsg.
> > recvMmsg/32 = 684,270 pps
> > recvmsg = 1,123,824 pps
>
> Can you test recv() as well?

Sure: https://github.com/netoptimizer/network-testing/commit/9e3c8b86a2d662

$ sudo taskset -c 1 ./udp_sink --port 9 --count $((10**6*2))
run count ns/pkt pps cycles payload
recvMmsg/32 run: 0 2000000 653.29 1530704.29 2351 18 demux:1
recvmsg run: 0 2000000 631.01 1584760.06 2271 18 demux:1
read run: 0 2000000 582.24 1717518.16 2096 18 demux:1
recvfrom run: 0 2000000 547.26 1827269.12 1970 18 demux:1
recv run: 0 2000000 547.37 1826930.39 1970 18 demux:1

> I think it might be faster than read().

Slightly, but same speed as recvfrom.

Strangely recvMmsg is not that bad in this testrun, and it is on the
same kernel 5.3.12-300.fc31.x86_64 and hardware. I have CPU pinned
udp_sink, as it if jumps to the CPU doing RX-NAPI it will be fighting
for CPU time with softirq (which have Eric mitigated a bit), and
results are bad and look like this:

[broadwell src]$ sudo taskset -c 5 ./udp_sink --port 9 --count $((10**6*2))
run count ns/pkt pps cycles payload
recvMmsg/32 run: 0 2000000 1252.44 798439.60 4508 18 demux:1
recvmsg run: 0 2000000 1917.65 521470.72 6903 18 demux:1
read run: 0 2000000 1817.31 550263.37 6542 18 demux:1
recvfrom run: 0 2000000 1742.44 573909.46 6272 18 demux:1
recv run: 0 2000000 1741.51 574213.08 6269 18 demux:1


> [...]
> > Found some old results (approx v4.10-rc1):
> >
> > [brouer@skylake src]$ sudo taskset -c 2 ./udp_sink --count $((10**7)) --port 9 --connect
> > recvMmsg/32 run: 0 10000000 537.89 1859106.74 2155 21559353816
> > recvmsg run: 0 10000000 552.69 1809344.44 2215 22152468673
> > read run: 0 10000000 476.65 2097970.76 1910 19104864199
> > recvfrom run: 0 10000000 450.76 2218492.60 1806 18066972794
>
> That is probably nearer what I am seeing on a 4.15 Ubuntu 18.04 kernel.
> recvmmsg() and recvmsg() are similar - but both a lot slower then recv().

Notice tool can also test connect UDP sockets, which is done in above.
I did a quick run with --connect:

$ sudo taskset -c 1 ./udp_sink --port 9 --count $((10**6*2)) --connect
run count ns/pkt pps cycles payload
recvMmsg/32 run: 0 2000000 500.72 1997107.02 1802 18 demux:1 c:1
recvmsg run: 0 2000000 662.52 1509380.46 2385 18 demux:1 c:1
read run: 0 2000000 613.46 1630103.14 2208 18 demux:1 c:1
recvfrom run: 0 2000000 577.71 1730974.34 2079 18 demux:1 c:1
recv run: 0 2000000 578.27 1729305.35 2081 18 demux:1 c:1

And now, recvMmsg is actually the fastest...?!


p.s.
DISPLAIMER: Do notice that this udp_sink tool is a network-overload
micro-benchmark, that does not represent the use-case you are
describing.
--
Best regards,
Jesper Dangaard Brouer
MSc.CS, Principal Kernel Engineer at Red Hat
LinkedIn: http://www.linkedin.com/in/brouer