GCE perf

[miekg]

I've started playing around in GCE.

3 machines:

• instance-1: n1-standard-2
• instance-2: n1-standard-4
• sender: n1-standard-4

All installed with Ubuntu-1703. CoreDNS is 007 (release from github).

[miekg]

Some simple queryperfing to get baseline:

0.2: Queries per second: 58800.788936 qps
0.3: Queries per second: 74555.654706 qps

[miekg]

Doing SO_REUSEADDR did not make any impact at all! REUSEPORT even made performace worse, don't know what I saw in #4, but can't easily replicate it.

[miekg]

Profile out when profiing: All this is done against the n1-standard-4 instance
Queries per second: 51117.913849 qps

% go tool pprof pprof.coredns.localhost:6053.samples.cpu.001.pb.gz                                                                ~/pprof deb
Entering interactive mode (type "help" for commands)
(pprof) top
24650ms of 48350ms total (50.98%)
Dropped 209 nodes (cum <= 241.75ms)
Showing top 10 nodes out of 161 (cum >= 1770ms)
      flat  flat%   sum%        cum   cum%
    9740ms 20.14% 20.14%    10280ms 21.26%  syscall.Syscall
    4170ms  8.62% 28.77%     4170ms  8.62%  runtime.futex
    2400ms  4.96% 33.73%     5760ms 11.91%  runtime.mallocgc
    1980ms  4.10% 37.83%     2740ms  5.67%  runtime.scanobject
    1490ms  3.08% 40.91%     1490ms  3.08%  runtime.epollwait
    1170ms  2.42% 43.33%     3290ms  6.80%  runtime.pcvalue
    1040ms  2.15% 45.48%     1040ms  2.15%  runtime.readvarint
    1000ms  2.07% 47.55%     1000ms  2.07%  runtime.usleep
     860ms  1.78% 49.33%     5830ms 12.06%  runtime.gentraceback
     800ms  1.65% 50.98%     1770ms  3.66%  github.com/coredns/coredns/vendor/github.com/miekg/dns.packDomainName

[miekg]

This looks pretty OK-ish.

pprof) cum
(pprof) top10
10.57s of 48.35s total (21.86%)
Dropped 209 nodes (cum <= 0.24s)
Showing top 10 nodes out of 161 (cum >= 9.85s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     35.03s 72.45%  runtime.goexit
     0.23s  0.48%  0.48%     24.35s 50.36%  github.com/coredns/coredns/vendor/github.com/miekg/dns.(*Server).serve
     0.02s 0.041%  0.52%     20.41s 42.21%  github.com/coredns/coredns/vendor/github.com/miekg/dns.HandlerFunc.ServeDNS
     0.02s 0.041%  0.56%     20.39s 42.17%  github.com/coredns/coredns/core/dnsserver.(*Server).ServePacket.func1
     0.21s  0.43%  0.99%     20.21s 41.80%  github.com/coredns/coredns/core/dnsserver.(*Server).ServeDNS
     0.02s 0.041%  1.03%     19.21s 39.73%  github.com/coredns/coredns/middleware/whoami.(*Whoami).ServeDNS
     0.26s  0.54%  1.57%     19.19s 39.69%  github.com/coredns/coredns/middleware/whoami.Whoami.ServeDNS
     0.05s   0.1%  1.68%     13.20s 27.30%  github.com/coredns/coredns/vendor/github.com/miekg/dns.(*response).WriteMsg
     9.74s 20.14% 21.82%     10.28s 21.26%  syscall.Syscall
     0.02s 0.041% 21.86%      9.85s 20.37%  github.com/coredns/coredns/vendor/github.com/miekg/dns.(*response).Write

[miekg]

Uploading the profile
pprof.coredns.localhost:6053.samples.cpu.001.pb.gz

[miekg]

Looking at the web view syscall.Syscall again stands out.

[miekg]

(pprof) text syscall.Syscall
10.21s of 48.35s total (21.12%)
Dropped 2 nodes (cum <= 0.24s)
Showing top 10 nodes out of 37 (cum >= 7.88s)
      flat  flat%   sum%        cum   cum%
     9.74s 20.14% 20.14%     10.28s 21.26%  syscall.Syscall
     0.20s  0.41% 20.56%      0.20s  0.41%  runtime.casgstatus
     0.12s  0.25% 20.81%      0.32s  0.66%  runtime.reentersyscall
     0.07s  0.14% 20.95%      0.21s  0.43%  runtime.exitsyscall
     0.07s  0.14% 21.10%      0.07s  0.14%  runtime.futex
     0.01s 0.021% 21.12%      0.33s  0.68%  runtime.entersyscall
         0     0% 21.12%      7.88s 16.30%  github.com/coredns/coredns/core/dnsserver.(*Server).ServeDNS
         0     0% 21.12%      2.40s  4.96%  github.com/coredns/coredns/core/dnsserver.(*Server).ServePacket
         0     0% 21.12%      7.88s 16.30%  github.com/coredns/coredns/core/dnsserver.(*Server).ServePacket.func1
         0     0% 21.12%      7.88s 16.30%  github.com/coredns/coredns/middleware/whoami.(*Whoami).ServeDNS

[miekg]

Well, syscall.Syscall just does the syscall and that takes time, (pprof) list syscall.Syscall shows the source which lists the children above (runtime.casgstatus and friends). So far this is actually WAI, but it does feel that something needs to be optimized here.

[miekg]

There are 2 things:

1. Is this syscall.Syscall an abnormal thing?
2. Should it be faster?

[miekg]

Ok

(pprof) list syscall.sendmsg
Total: 48.35s
ROUTINE ======================== syscall.sendmsg in /home/miek/upstream/go/src/syscall/zsyscall_linux_amd64.go
      10ms      7.89s (flat, cum) 16.32% of Total
         .          .   1745:}
         .          .   1746:
         .          .   1747:// THIS FILE IS GENERATED BY THE COMMAND AT THE TOP; DO NOT EDIT
         .          .   1748:
         .          .   1749:func sendmsg(s int, msg *Msghdr, flags int) (n int, err error) {
         .      7.88s   1750:	r0, _, e1 := Syscall(SYS_SENDMSG, uintptr(s), uintptr(unsafe.Pointer(msg)), uintptr(flags))
         .          .   1751:	n = int(r0)
         .          .   1752:	if e1 != 0 {
         .          .   1753:		err = errnoErr(e1)
         .          .   1754:	}
      10ms       10ms   1755:	return
         .          .   1756:}
         .          .   1757:
         .          .   1758:// THIS FILE IS GENERATED BY THE COMMAND AT THE TOP; DO NOT EDIT
         .          .   1759:
         .          .   1760:func mmap(addr uintptr, length uintptr, prot int, flags int, fd int, offset int64) (xaddr uintptr, err error) {

The syscall is sending the message. Makes sense looks legit, i.e. answer 1) from above

[miekg]

Ah, the slowness might be the use of defer() in my patch to Go DNS. I'll retest.
Not true, this is called once on the socket.

[miekg]

No using any of the functions in udp_linux.go, results in similar profile. With a large chunk taken by Syscall:

26030ms of 52680ms total (49.41%)
Dropped 220 nodes (cum <= 263.40ms)
Showing top 10 nodes out of 156 (cum >= 2040ms)
      flat  flat%   sum%        cum   cum%
    9430ms 17.90% 17.90%     9890ms 18.77%  syscall.Syscall
    4550ms  8.64% 26.54%     4550ms  8.64%  runtime.futex
    2760ms  5.24% 31.78%     6890ms 13.08%  runtime.mallocgc
    2690ms  5.11% 36.88%     3600ms  6.83%  runtime.scanobject
    1600ms  3.04% 39.92%     4200ms  7.97%  runtime.pcvalue
    1250ms  2.37% 42.29%     1250ms  2.37%  runtime.readvarint
    1200ms  2.28% 44.57%     1200ms  2.28%  runtime.epollwait
     970ms  1.84% 46.41%     2400ms  4.56%  github.com/coredns/coredns/vendor/github.com/miekg/dns.packDomainName
     790ms  1.50% 47.91%     6850ms 13.00%  runtime.gentraceback
     790ms  1.50% 49.41%     2040ms  3.87%  runtime.step

It is nice to see dns.packDomainName, but just writing responses takes 3x longer....

[miekg]

OK, completely removing OOB UDP sending does not impact performace, hovers around 70K qps.

Going to kernel for sending these udp packets is slow (and we do it for every packet). Now starting to wonder how other UDP servers deal with this.

[miekg]

@johnbelamaric do you know how this is optimized in C programs?

[miekg]

This also explains the speedup that I saw locally (although not the 3x increase), but AFAICT linux optimizes out the network when going through localhost - which means no kernel context switch..???