Huge amount of context switches, growing over time

[okket]

When I let ipfs daemon run for about 48 hours my system starts to show latency issues due to a huge amount of context switches. They slowly grow over time and are directly attributable to ipfs (the problem does not exist without running the daemon).

Here is a nice graph to illustrate:

Every other metric, like packets per second (about 300), connections (about 50), memory usage, etc. does not grow out of bounds.

Guesswork: With vmstat 1 I see nearly exactly ever 10 seconds a huge spike in context switches, currently about 20k. I am somewhat sure that this is daemon.

I'll update this issue tomorrow with fresh numbers and hopefully a dump of the daemon.

[whyrusleeping]

So, the next time you see this hapening, if i could get the output of ps -eLf | grep ipfs and also the stack dump from pressing Ctrl + \

[okket]

ps -eLf | grep ipfs yields:

ipfs     10438 29363 10438  0    1 05:02 pts/0    00:00:00 ps -eLf
ipfs     10439 29363 10439  0    1 05:02 pts/0    00:00:00 grep --color=auto -i ipfs
ipfs     22072     1 22072  0    1 Apr07 ?        00:00:01 tmux
ipfs     22073 22072 22073  0    1 Apr07 pts/1    00:00:00 -bash
ipfs     22167 22073 22167  0  117 Apr07 pts/1    00:00:00 ipfs daemon
[...]
ipfs     22167 22073 22317  0  117 Apr07 pts/1    00:00:00 ipfs daemon

I can get a core dump of the running process with gcore -o <file> <pid>. Does this help? Or do you need the dump of the terminated process? The latter is a bit more tricky, the environment options did not allow core dumps when the process was started. The best idea I have is to somehow halt the process (with a signal?) and then gcore.

[okket]

A 1-2 minute strace summary:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 72.33    9.250829          96     96790     31186 futex
 22.64    2.895659         119     24235           epoll_wait
  3.81    0.487598          14     35409           select
  0.63    0.080998           3     30416      2570 read
  0.43    0.054642           3     16720           write
  0.11    0.013771        6886         2         1 restart_syscall
  0.05    0.006987           2      3154           sched_yield
------ ----------- ----------- --------- --------- ----------------
100.00   12.790484                206726     33757 total

A short system call trace of one of the threads:

22168      0.000047 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
22168      0.000041 <... restart_syscall resumed> ) = 0
22168      0.000041 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
22168      0.000026 <... select resumed> ) = 0 (Timeout)
22168      0.000026 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
22168      0.000106 <... select resumed> ) = 0 (Timeout)
22168      0.000042 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
22168      0.000051 <... select resumed> ) = 0 (Timeout)
22168      0.000041 futex(0x1083a40, FUTEX_WAIT, 0, {60, 0} <unfinished ...>
22168      0.000047 <... futex resumed> ) = 0
22168      0.000047 select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
22168      0.000057 <... select resumed> ) = 0 (Timeout)
[...]

[whyrusleeping]

if you send the process SIGQUIT it will dump all the goroutine stacks.

But thats a lot of threads, and quite the large number of calls to futex, epoll_wait and select... Looks to me like a goroutine leak

[jbenet]

I'll push a changeset that adds an option to disable reuseport. would be good to see the numbers then.

[okket]

Sounds great. I'll gladly try that changeset and report.

I also managed to get the last 2k lines of the kill -SIGQUIT output out of the tmux session. The IPFS hash for the file is QmYGvyL3ZUQaQqwk9Zc4uUrpxWG42gh7X86UhRPeeU92U4

Here is an updated graph which shows the daemon restart

[jbenet]

@okket changeset available in the branch for #1038 -- it will be merged soon too.

[okket]

Thank you for merging. I'm running the master branch now with IPFS_REUSEPORT=false ipfs daemon, but I am not sure the new code gets called. The small typo (log.Infof, see #1042) did not error. Consequently I do not see the confirmation message in the logs.

[okket]

Ok, my reasoning was, hmm, just wrong. Sorry. Since I am not able to catch the log message for some reason I just changed the log_Infof into a print in my test setup. The code is called and hopefully the daemon now does not eat up resources over time. I'll report in a day or two.

Still I find the amount of system calls the daemon emits a bit alarming:

$ timeout 60 strace -c -f -p $(pidof ipfs)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 72.08    3.705090         103     36124      3984 futex
 19.80    1.017752          38     26701           epoll_wait
  6.25    0.321034          18     17715           select
  1.03    0.053204           2     25965      2644 read
  0.75    0.038429           3     15155           write
  0.08    0.004328           3      1562           sched_yield
  0.01    0.000512          73         7           madvise
  0.00    0.000167          84         2         1 restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00    5.140516                123231      6629 total

[whyrusleeping]

@okket that is pretty concerning. the futex is goroutine scheduling going on, and it implies we probably have too many goroutines. epoll_wait is typically in the network stack, i know that the REUSEPORT code makes a large number of calls to it, go/net probably does as well.

At any rate, i think some profiling needs to be done. and eventlogs need to be turned off.

[okket]

Preliminary results indicate that current master with IPFS_REUSEPORT=false ipfs daemon is still generating more context switches over time:

[okket]

I forgot to mention: Because Fedora does not include P-224 (for patent reasons I guess) I had to remove support from ipfs:

diff --git a/p2p/crypto/key.go b/p2p/crypto/key.go
index 7f0a13a..31dfeb3 100644
--- a/p2p/crypto/key.go
+++ b/p2p/crypto/key.go
@@ -102,8 +102,8 @@ func GenerateEKeyPair(curveName string) ([]byte, GenSharedKey, error) {
        var curve elliptic.Curve

        switch curveName {
-       case "P-224":
-               curve = elliptic.P224()
+//     case "P-224":
+//             curve = elliptic.P224()
        case "P-256":
                curve = elliptic.P256()
        case "P-384":
diff --git a/p2p/crypto/secio/al.go b/p2p/crypto/secio/al.go
index 9a0cadf..9e0ffce 100644
--- a/p2p/crypto/secio/al.go
+++ b/p2p/crypto/secio/al.go
@@ -18,7 +18,7 @@ import (
 )

 // List of supported ECDH curves
-var SupportedExchanges = "P-256,P-224,P-384,P-521"
+var SupportedExchanges = "P-256,P-384,P-521"

 // List of supported Ciphers
 var SupportedCiphers = "AES-256,AES-128,Blowfish"

I hope this change does not in a crazy way I can not possibly imagine create a feedback loop or trigger another thing that is responsible for the growing context switch problem.

[whyrusleeping]

I dont see why fedora not having it means you have to remove it from ipfs, p224 is a go library.

[whyrusleeping]

Also, i have two fedora boxes running ipfs without modification just fine. You may be running an older version of Go?

[okket]

Nope:

$ yum info golang
Loaded plugins: langpacks
Installed Packages
Name        : golang
Arch        : x86_64
Version     : 1.4.2
Release     : 2.fc21
Size        : 10 M
Repo        : installed
From repo   : updates
Summary     : The Go Programming Language
URL         : http://golang.org/
License     : BSD
Description : The Go Programming Language.

The build fails with P-224 support:

$ make build
cd cmd/ipfs && go build -i
# github.com/ipfs/go-ipfs/p2p/crypto
../../../gocode/src/github.com/ipfs/go-ipfs/p2p/crypto/key.go:106: undefined: elliptic.P224
Makefile:27: recipe for target 'build' failed
make: *** [build] Error 2