| 1 | # General performance debugging guidelines |
| 2 | |
| 3 | This is a document for helping debug Kubo. Please add to it if you can! |
| 4 | |
| 5 | # Table of Contents |
| 6 | |
| 7 | - [General performance debugging guidelines](#general-performance-debugging-guidelines) |
| 8 | - [Table of Contents](#table-of-contents) |
| 9 | - [Beginning](#beginning) |
| 10 | - [Known logger subsystems](#known-logger-subsystems) |
| 11 | - [Analyzing the stack dump](#analyzing-the-stack-dump) |
| 12 | - [Analyzing the CPU Profile](#analyzing-the-cpu-profile) |
| 13 | - [Analyzing vars and memory statistics](#analyzing-vars-and-memory-statistics) |
| 14 | - [Tracing](#tracing) |
| 15 | - [Other](#other) |
| 16 | |
| 17 | ### Beginning |
| 18 | |
| 19 | > **Note:** Enable more logs by setting `GOLOG_LOG_LEVEL` env variable when troubleshooting. See [go-log documentation](https://github.com/ipfs/go-log#golog_log_level) for configuration options and available log levels. |
| 20 | |
| 21 | When you see ipfs doing something (using lots of CPU, memory, or otherwise |
| 22 | being weird), the first thing you want to do is gather all the relevant |
| 23 | profiling information. |
| 24 | |
| 25 | There's a command (`ipfs diag profile`) that will do this for you and |
| 26 | bundle the results up into a zip file, ready to be attached to a bug report. |
| 27 | |
| 28 | If you feel intrepid, you can dump this information and investigate it yourself: |
| 29 | |
| 30 | - goroutine dump |
| 31 | - `curl localhost:5001/debug/pprof/goroutine\?debug=2 > ipfs.stacks` |
| 32 | - 30 second cpu profile |
| 33 | - `curl localhost:5001/debug/pprof/profile > ipfs.cpuprof` |
| 34 | - heap trace dump |
| 35 | - `curl localhost:5001/debug/pprof/heap > ipfs.heap` |
| 36 | - memory statistics (in json, see "memstats" object) |
| 37 | - `curl localhost:5001/debug/vars > ipfs.vars` |
| 38 | - system information |
| 39 | - `ipfs diag sys > ipfs.sysinfo` |
| 40 | |
| 41 | |
| 42 | ### Known logger subsystems |
| 43 | |
| 44 | `GOLOG_LOG_LEVEL` matches subsystem names exactly (no prefix or wildcard matching beyond `*` for "all subsystems"). The same names work with the runtime command `ipfs log level <subsystem> <level>`. The list below covers the outbound provide/reprovide pipeline, which spans multiple packages and therefore multiple subsystems. |
| 45 | |
| 46 | | Subsystem | Source | Purpose | |
| 47 | | --- | --- | --- | |
| 48 | | `provider` | kubo `core/node`, boxo `provider` | Kubo provider orchestration (keystore lifecycle, strategy changes, reprovide cycle start/finish, throughput alarms) and boxo's legacy provider system (active when `Provide.DHT.SweepEnabled=false` or for non-DHT routers) | |
| 49 | | `dht/provider` | `go-libp2p-kad-dht` | Sweep-based DHT provider (active when `Provide.DHT.SweepEnabled=true`, the default), including the buffered wrapper, keystore, and resettable keystore | |
| 50 | | `dht/provider/lan` | `go-libp2p-kad-dht` (dual) | LAN half of the dual DHT provider; the WAN half reuses `dht/provider` | |
| 51 | | `dsqueue` | `go-dsqueue` | Generic datastore queue used by the legacy provider queue | |
| 52 | |
| 53 | To see everything the provide system emits, for example at `debug` level: |
| 54 | |
| 55 | ```shell |
| 56 | GOLOG_LOG_LEVEL="provider=debug,dht/provider=debug,dht/provider/lan=debug" ipfs daemon |
| 57 | ``` |
| 58 | |
| 59 | ### Analyzing the stack dump |
| 60 | |
| 61 | The first thing to look for is hung goroutines -- any goroutine that's been stuck |
| 62 | for over a minute will note that in the trace. It looks something like: |
| 63 | |
| 64 | ``` |
| 65 | goroutine 2306090 [semacquire, 458 minutes]: |
| 66 | sync.runtime_Semacquire(0xc8222fd3e4) |
| 67 | /home/whyrusleeping/go/src/runtime/sema.go:47 +0x26 |
| 68 | sync.(*Mutex).Lock(0xc8222fd3e0) |
| 69 | /home/whyrusleeping/go/src/sync/mutex.go:83 +0x1c4 |
| 70 | gx/ipfs/QmedFDs1WHcv3bcknfo64dw4mT1112yptW1H65Y2Wc7KTV/yamux.(*Session).Close(0xc8222fd340, 0x0, 0x0) |
| 71 | /home/whyrusleeping/gopkg/src/gx/ipfs/QmedFDs1WHcv3bcknfo64dw4mT1112yptW1H65Y2Wc7KTV/yamux/session.go:205 +0x55 |
| 72 | gx/ipfs/QmWSJzRkCMJFHYUQZxKwPX8WA7XipaPtfiwMPARP51ymfn/go-stream-muxer/yamux.(*conn).Close(0xc8222fd340, 0x0, 0x0) |
| 73 | /home/whyrusleeping/gopkg/src/gx/ipfs/QmWSJzRkCMJFHYUQZxKwPX8WA7XipaPtfiwMPARP51ymfn/go-stream-muxer/yamux/yamux.go:39 +0x2d |
| 74 | gx/ipfs/QmZK81vcgMhpb2t7GNbozk7qzt6Rj4zFqitpvsWT9mduW8/go-peerstream.(*Conn).Close(0xc8257a2000, 0x0, 0x0) |
| 75 | /home/whyrusleeping/gopkg/src/gx/ipfs/QmZK81vcgMhpb2t7GNbozk7qzt6Rj4zFqitpvsWT9mduW8/go-peerstream/conn.go:156 +0x1f2 |
| 76 | created by gx/ipfs/QmZK81vcgMhpb2t7GNbozk7qzt6Rj4zFqitpvsWT9mduW8/go-peerstream.(*Conn).GoClose |
| 77 | /home/whyrusleeping/gopkg/src/gx/ipfs/QmZK81vcgMhpb2t7GNbozk7qzt6Rj4zFqitpvsWT9mduW8/go-peerstream/conn.go:131 +0xab |
| 78 | ``` |
| 79 | |
| 80 | At the top, you can see that this goroutine (number 2306090) has been waiting |
| 81 | to acquire a semaphore for 458 minutes. That seems bad. Looking at the rest of |
| 82 | the trace, we see the exact line it's waiting on is line 47 of runtime/sema.go. |
| 83 | That's not particularly helpful, so we move on. Next, we see that call was made |
| 84 | by line 205 of yamux/session.go in the `Close` method of `yamux.Session`. This |
| 85 | one appears to be the issue. |
| 86 | |
| 87 | Given that information, look for another goroutine that might be |
| 88 | holding the semaphore in question in the rest of the stack dump. |
| 89 | (If you need help doing this, ping and we'll stub this out.) |
| 90 | |
| 91 | There are a few different reasons that goroutines can be hung: |
| 92 | - `semacquire` means we're waiting to take a lock or semaphore. |
| 93 | - `select` means that the goroutine is hanging in a select statement and none of |
| 94 | the cases are yielding anything. |
| 95 | - `chan receive` and `chan send` are waiting for a channel to be received from |
| 96 | or sent on, respectively. |
| 97 | - `IO wait` generally means that we are waiting on a socket to read or write |
| 98 | data, although it *can* mean we are waiting on a very slow filesystem. |
| 99 | |
| 100 | If you see any of those tags _without_ a `, |
| 101 | X minutes` suffix, that generally means there isn't a problem -- you just caught |
| 102 | that goroutine in the middle of a short wait for something. If the wait time is |
| 103 | over a few minutes, that either means that goroutine doesn't do much, or |
| 104 | something is pretty wrong. |
| 105 | |
| 106 | If you're seeing a lot of goroutines, consider using |
| 107 | [stackparse](https://github.com/whyrusleeping/stackparse) to filter, sort, and summarize them. |
| 108 | |
| 109 | ### Analyzing the CPU Profile |
| 110 | |
| 111 | The go team wrote an [excellent article on profiling go |
| 112 | programs](http://blog.golang.org/profiling-go-programs). If you've already |
| 113 | gathered the above information, you can skip down to where they start talking |
| 114 | about `go tool pprof`. My go-to method of analyzing these is to run the `web` |
| 115 | command, which generates an SVG dotgraph and opens it in your browser. This is |
| 116 | the quickest way to easily point out where the hot spots in the code are. |
| 117 | |
| 118 | ### Analyzing vars and memory statistics |
| 119 | |
| 120 | The output is JSON formatted and includes badger store statistics, the command line run, and the output from Go's [runtime.ReadMemStats](https://golang.org/pkg/runtime/#ReadMemStats). The [MemStats](https://golang.org/pkg/runtime/#MemStats) has useful information about memory allocation and garbage collection. |
| 121 | |
| 122 | ### Tracing |
| 123 | |
| 124 | Experimental tracing via OpenTelemetry suite of tools is available. |
| 125 | See `tracing/doc.go` for more details. |
| 126 | |
| 127 | ### Other |
| 128 | |
| 129 | If you have any questions, or want us to analyze some weird kubo behavior, |
| 130 | just let us know, and be sure to include all the profiling information |
| 131 | mentioned at the top. |