glusterd2/doc/profiling.md

Tracking resource usage in Glusterd2
====================================

Tracing and profiling with `pprof` is intended for developers only. This can be
used for debugging memory leaks/consumption, slow flows through the code and so
on. Users will normally not want profiling enabled on their production systems.
To investigate memory allocations in Glusterd2, it is needed to enable the
profiling feature. This can be done by adding `"profiling": true` in
the `--config` file.
Enabling profiling makes standard Golang pprof endpoints available. For memory
allocations `/debug/pprof/heap` is most useful.
Capturing a snapshot of the current allocations in the Glusterd2 is pretty
simple. On the node running Glusterd2, the go pprof tool command can be used:
```
[root@fedora3 glusterd2]# go tool pprof http://localhost:24007/debug/pprof/heap
File: glusterd2
Build ID: 7a94c2e498445577aaf7f910d6ef1c3adc19d553
Type: inuse_space
Time: Nov 28, 2018 at 2:55pm (IST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
```

For working with the size of the allocations, it is helpful to set all sizes to
`megabytes`, otherwise `auto` is used as a `unit` and that would add human
readable B, kB, MB postfixes. This however is not useful for sorting with
scripts. So, set the `unit` to `megabytes` instead:

```
(pprof) unit=megabytes
```

```
(pprof) top
Showing nodes accounting for 330.75MB, 98.52% of 335.73MB total
Dropped 305 nodes (cum <= 1.68MB)
Showing top 10 nodes out of 14
      flat  flat%   sum%        cum   cum%
     326MB 97.10% 97.10%      326MB 97.10%  github.com/gluster/glusterd2/pkg/sunrpc.ReadFullRecord /root/work/src/github.com/gluster/glusterd2/pkg/sunrpc/record.go
    2.38MB  0.71% 97.81%     2.38MB  0.71%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/rafthttp.startStreamWriter /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/rafthttp/stream.go
    2.38MB  0.71% 98.52%     4.77MB  1.42%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/rafthttp.startPeer /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/rafthttp/peer.go
         0     0% 98.52%   326.01MB 97.10%  github.com/gluster/glusterd2/pkg/sunrpc.(*serverCodec).ReadRequestHeader /root/work/src/github.com/gluster/glusterd2/pkg/sunrpc/servercodec.go
         0     0% 98.52%     4.83MB  1.44%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).apply /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver/server.go
         0     0% 98.52%     4.83MB  1.44%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).applyAll /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver/server.go
         0     0% 98.52%     4.77MB  1.42%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).applyConfChange /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver/server.go
         0     0% 98.52%     4.83MB  1.44%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).applyEntries /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver/server.go
         0     0% 98.52%     4.83MB  1.44%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver.(*EtcdServer).run.func6 /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/etcdserver/server.go
         0     0% 98.52%     4.83MB  1.44%  github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/pkg/schedule.(*fifo).run /root/work/src/github.com/gluster/glusterd2/vendor/github.com/coreos/etcd/pkg/schedule/schedule.go
(pprof)
```

Looking at the above output, we can see that the first line consumes hundreds
of MB while the other lines are just a fraction of it.
This makes sure that ReadFullRecord is consuming more memory than required.
To understand things even more clearly, we can see which line of ReadFullRecord
consumes the memory. To view that use the list command:

```
(pprof) list ReadFullRecord
Total: 335.73MB
ROUTINE ======================== github.com/gluster/glusterd2/pkg/sunrpc.ReadFullRecord in /root/work/src/github.com/gluster/glusterd2/pkg/sunrpc/clientcodec.go
    8.11kB     8.11kB (flat, cum) 0.0024% of Total
         .          .      1:package sunrpc
         .          .      2:
         .          .      3:import (
    8.11kB     8.11kB      4:	"bytes"
         .          .      5:	"io"
         .          .      6:	"net"
         .          .      7:	"net/rpc"
         .          .      8:	"sync"
         .          .      9:
ROUTINE ======================== github.com/gluster/glusterd2/pkg/sunrpc.ReadFullRecord in /root/work/src/github.com/gluster/glusterd2/pkg/sunrpc/record.go
     326MB      326MB (flat, cum) 97.10% of Total
         .          .     96:func ReadFullRecord(conn io.Reader) ([]byte, error) {
         .          .     97:
         .          .     98:	// In almost all cases, RPC message contain only one fragment which
         .          .     99:	// is not too big in size. But set a cap on buffer size to prevent
         .          .    100:	// rogue clients from filling up memory.
     326MB      326MB    101:	record := bytes.NewBuffer(make([]byte, 0, maxRecordSize))
         .          .    102:	var fragmentHeader uint32
         .          .    103:	for {
         .          .    104:		// Read record fragment header
         .          .    105:		err := binary.Read(conn, binary.BigEndian, &fragmentHeader)
         .          .    106:		if err != nil {
(pprof)
```

The records allocation is the culprit and we need to look further into
the code as to why the records is allocating so much and fix it.