Performance analysis of our own full blown HTTP server with Netty 4

In previous post Let's do our own full blown HTTP server with Netty 4 you and I were excited by creation of our own web server. So far so good. But how good?

CORAID speed test

Hardware: 2x10Gb link, 36x2TB drives on CORAID SRX 4200.

aoe-stat
e0.X 2000.398GB eth2,eth3 8704 up
(36 drives total)
ethtool eth2
Speed: 10000Mb/s
ethtool eth3
Speed: 10000Mb/s
 
cec -s 0 eth2
disks
0.0 2000.398GB X.0.0 WDC WD2003FYYS-02W0B0 01.01D01 sata 3.0Gb/s
(36 drives total)
list -l
X 2000.399GB online
X.0 2000.399GB jbod normal
X.0.0 normal 2000.399GB 0.X
(36 JBODs total)

CORAID raw device speed (using aio, O_DIRECT to omit the cache, O_SYNC and different RAID types):

• JBODs, 36 LUNs per 2TB, 4 simultaneous request/LUN, read and write by 4K blocks

50% reads, 50% writes = 220.45 iops/LUN, 2m5.678s/1000000 blocks
reads = 163.39 iops/LUN, 2m49.834s/1000000 blocks
writes = 455.37 iops/LUN, 1m0.602s/1000000 blocks

• raid6rs, 4 LUNs per 14TB, 100 simultaneous request/LUN, read and write by 4K blocks

50% reads, 50% writes = 274.72 iops/LUN, 1m31.482s/100000 blocks
reads = 1524.39 iops/LUN, 2m43.648s/1000000 blocks
writes = 164.47 iops/LUN, 2m31.699s/100000 blocks

• raid5, 4 LUNs per 16TB, 100 simultaneous request/LUN, read and write by 4K blocks

50% reads, 50% writes = 827.81 iops/LUN, 2m31.095s/500000 blocks
reads = 1519.94 iops/LUN, 2m44.482s/1000000 blocks
writes = 555.55 iops/LUN, 0m44.665s/100000 blocks

See the test program. You need libaio for it (POSIX aio in librt uses pthreads which is not appropriate because of massive parallelism in our tests).

Xenoprof, Xen profiling

Xenoprof is a system-wide profiler for Xen virtual machine environments, capable of profiling the Xen virtual machine monitor, multiple Linux guest operating systems, and applications running on them. (http://xenoprof.sourceforge.net/)

A little bit outdated but still useful Xenoprof overview & Networking Performance Analysis.

How to debug Sun RPC

I bet you used to debug web services via some sniffer like wireshark. This is possible because of protocol simplicity (yes, event if it is SOAP with attachments it is still simple text xml based protocol).
Sun RPC is rather popular IPC mechanism on Linux, it reminds Java Sun RMI by its nature. Sun RPC is complex, binary and uses multiple connections. In brief there is an rpcbind daemon (or portmapper in other words) that is a registry of services, client asks rpcbind about port of specific service and then connects directly to service. For instance, NFS is build around Sun RPC, nfs-server uses 2049 port by default but it can be registered on any other port and clients still can find it by registry (nfs-utils prior to 1.2 has hardcoded 2049 port though).

So how to deal with this if you hit some trouble? There is an rpcdebug util

The rpcdebug command allows an administrator to set and clear the Linux kernel's NFS client and server debug flags. Setting these flags causes the kernel to emit messages to the system log in response to NFS activity; this is typically useful when debugging NFS problems.

rpcdebug -vh
usage: rpcdebug [-v] [-h] [-m module] [-s flags...|-c flags...]
       set or cancel debug flags.

Module     Valid flags
rpc        xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache all
nfs        vfs dircache lookupcache pagecache proc xdr file root callback client mount all
nfsd       sock fh export svc proc fileop auth repcache xdr lockd all
nlm        svc client clntlock svclock monitor clntsubs svcsubs hostcache xdr all

rpcdebug -m rpc -s all
rpc        xprt call debug nfs auth bind sched trans svcsock svcdsp misc cache

See /var/log/syslog

...
Jan  6 13:40:58 HDC05 kernel: [1430624.387439] RPC:       set up transport to address addr=10.1.2.11 port=48355 proto=udp
Jan  6 13:40:58 HDC05 kernel: [1430624.387533] RPC:       created transport ffff88000eb2c000 with 16 slots
Jan  6 13:40:58 HDC05 kernel: [1430624.387588] RPC:       creating mount client for db01 (xprt ffff88000eb2c000)
Jan  6 13:40:58 HDC05 kernel: [1430624.387672] RPC:       creating UNIX authenticator for client ffff88002f863200
Jan  6 13:40:58 HDC05 kernel: [1430624.389041] RPC:     0 holding NULL cred ffffffffa0118da0
Jan  6 13:40:58 HDC05 kernel: [1430624.389091] RPC:       new task initialized, procpid 21435
Jan  6 13:40:58 HDC05 kernel: [1430624.389142] RPC:       allocated task ffff88002b3fe1c0
Jan  6 13:40:58 HDC05 kernel: [1430624.389192] RPC:   850 __rpc_execute flags=0x280
Jan  6 13:40:58 HDC05 kernel: [1430624.389240] RPC:   850 call_start mount3 proc NULL (sync)
Jan  6 13:40:58 HDC05 kernel: [1430624.389290] RPC:   850 call_reserve (status 0)
...

Debug and profile erlang linked in driver

OTP tools like fprof refuse to profile your .so (for a good reason). So how to do this?
erl is like any other executable loads linked in driver as a shared library and one can intorspect this shared library like any other. During compilation one need to add debug info to .so file (-ggdb flag for gcc) then attach to running erlang virtual machine from gdb or kdbg or similar.

> ps ax | grep erlang
 9801 pts/1    Sl+    0:00 /usr/lib64/erlang/erts-5.8.1/bin/beam.smp -K true -- -root /usr/lib64/erlang -progname erl -- -home /home/adolgarev --
11208 pts/0    S+     0:00 grep erlang
> kdbg -p 9801 /usr/lib64/erlang/erts-5.8.1/bin/beam.smp

Now breakpoints can be added and program state inspected

To profile do the following

valgrind --tool=callgrind --trace-children=yes /usr/bin/erl

Run tests, grab callgrind.out.PID, open it in kcachegrind

In this particular example you can see cons (|) for list creation is really slow (procedure ei_x_encode_list_header). Knowing list size beforehand decreases caller relative execution time from 34.45% to 23.25%.

Note that profiling is not a sign of premature optimization but also a sanity check that you do not do some insane things.

Python, profiling

'Have you seen python web developers who do high load site development for living?'
'Oh, almost all of them do such things,' you say.
'Have you seen python devs who know how to debug?'
'A few,' you say.
'Have you seen python devs who profile things that supposed to be high loaded?'

Python has cProfile, C has kcachegrind, they look good together.

For instance, lets profile multithreaded wsgi app. Change your handler

def read(self, request, *args, **kwargs):
    ...
    return ...

To something like

def read(self, *args, **kwargs):
    import cProfile
    import uuid
    cProfile.runctx('self.read2(*args, **kwargs)', globals(), locals(),
        '/folder_with_stats/' + uuid.uuid4().get_hex())
    return self.__res

def read2(self, *args, **kwargs):
    self.__res = self.read3(*args, **kwargs)

def read3(self, request, *args, **kwargs):
    ...
    return ...

Then (high) load your app. Gather results from folder_with_stats

import os
import pstats
import time
from pyprof2calltree import convert

# Collect stats
p = None
for i in os.listdir('/folder_with_stats'):
    filename = '/folder_with_stats/' + i
    if not p:
        p = pstats.Stats(filename)
    else:
        p.add(filename)
    os.unlink(filename)
res = str(int(time.time())) + '.kgrind'
convert(p, res)

os.execlp('kcachegrind', res)

The main thing here to note is pyprof2calltree. The result

If you want httperf with libev on board

Ab eats CPU, so does httperf. Use Weighttp

weighttp -n 1000000 -c 100 -t 10 -k http://localhost/