feat(cli): A: Add ability to dump pprof data to logs ...

[aaron-kasten]

This PR adds the ability to dump pprof data to logs for debugging.

This is one of 4 PRs in a PR train:
aaron-kasten/kopia:pprof-extensions-A
aaron-kasten/kopia:pprof-extensions-B
aaron-kasten/kopia:pprof-extensions-C
aaron-kasten/kopia:pprof-extensions-D

Usage

pprof dumps are configured using the KOPIA_DEBUG_PPROF environment variable. The variable is a list of pprof profile names (see pprof.Lookup) separated by ,. Optional parameters can be set with '=', delimited by ':'.

example:

export KOPIA_DEBUG_PPROF=cpu,heap=debug=1,mutex=debug=1:rate=1000

The above setting will produce CPU, heap and mutex profiles. The block profile will have its debug parameter set to 1 and its sample rate set to 1000

Once run, profile data will be output in the Kopia logs on termination. Profile dumps are generated as base64 output (PEM) to the log on termination.

You should consider captureing logs to a file when running the Kopia command:

$ kopia --log-file ./myout.log snapshot create . &
[1] 77308

Once the logs are captured, a dump can created by terminating the command:

$ kill %1

The following signals (on Linux and macos) can be used to dump profiles: SIGTERM, SIGINT, and SIGUSR1.

Captured standard-output should look similar to:

saving PEM buffers for output
2021/11/16 19:38:59 Shutting down...
dumping PEM for "PPROF MEM"
-----BEGIN PPROF MEM-----
H4sIAAAAAAAE/7R8CXxURfIw3ZOEJkTTGUUK8Hg8FZMoM8kDBHTXlUtFPBDwWteN
w+RlGJnMG2cmIO7uf4PcN8qtcsqNXCIgghgQBMUL8RYVFPHAAw/UVdTvV9VvzswE
.
.
.
sOBRWRMwE4RCnvDAimrjlBhatdcTCGSqZ9kAbk+k2i4YRBLMVXsCvgQzQXNwKGzh
l3HYSLE3drEgweOQCN7Jjnq8A43CtKt5Rt5tgyoj1u1G/m2DIkMiXk8gcPv/CwAA
//8psEjOrZ4AAA==
-----END PPROF MEM-----

The captured output can then be converted to a pprof binary by using kats. The Kopia kats tool can be used to convert the PEM file into a binary:

$ ./go/bin/kats dump.b64
writing PEM "PPROF MEM" to file "pprof_mem.bin"

When successful, kats will output the file found in the capture file.

kats expects that there is a well formed PEM record in the capture file.

 ./go/bin/kats --help
 Usage of ./go/bin/kats:
  -verbose
    	verbose outout

Once successful, the binary can be used in PPROF:

$ go tool pprof ./pprof_mem.bin
File: pprof_mem.bin
Type: inuse_space
Time: Nov 16, 2021 at 11:38am (PST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) tree
Showing nodes accounting for 35248.89kB, 100% of 35248.89kB total
Showing top 80 nodes out of 127
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context
----------------------------------------------------------+-------------
   16384kB 46.48% 46.48%    16384kB 46.48%                | kopia/tracing.StartProfileBuffers
----------------------------------------------------------+-------------
                                         2561.41kB   100% |   encoding/json.(*decodeState).object
 2561.41kB  7.27% 53.75%  2561.41kB  7.27%                | reflect.mapassign

Configuration Options

TBD

[julio-lopez]

@aaron-kasten The steps below allow you to directly get pprof files in (binary) protobuf format that can be then directly loaded in go tool pprof. This allows getting the required pprof files, already separated without the need to encode them and then decode them. This assumes, a long running kopia process, for example, in the case of a large snapshot.

Would that approach work for your use case? if not, why not?

# 1. start the kopia process with a metrics listener and enable pprof. This assumes, it is
# a long running process. For example:

kopia --metrics-listen-addr localhost:10005 --enable-pprof snapshot create &

# 2. periodically get various pprof dumps from the metrics endpoint using go tool pprof

go tool pprof -proto  http://localhost:10005/debug/pprof/profile

# output:
#
# The obtained pprof file can be examined directly with go pprof
# Fetching profile over HTTP from http://localhost:10005/debug/pprof/profile
# Saved profile in ${HOME}/pprof/pprof.samples.cpu.002.pb.gz
# Generating report in profile001.pb.gz

# 3. load pprof file, for example, using the built-in web UI

go tool pprof -http localhost:5000 $HOME/pprof/pprof.samples.cpu.001.pb.gz

Other kopia pprof endpoints:
/debug/pprof/cmdline
/debug/pprof/profile
/debug/pprof/symbol
/debug/pprof/trace

[aaron-kasten]

@julio-lopez

@aaron-kasten The steps below allow you to directly get pprof files in (binary) protobuf format that can be then directly loaded in go tool pprof. This allows getting the required pprof files, already separated without the need to encode them and then decode them.

Would that approach work for your use case? if not, why not?

# 1. start the kopia process with a metrics listener and enable pprof. For example:

kopia --metrics-listen-addr localhost:10005 --enable-pprof snapshot create &

# 2. periodically get various pprof dumps from the metrics endpoint using go tool pprof

go tool pprof -proto  http://localhost:10005/debug/pprof/profile

# output:
#
# The obtained pprof file can be examined directly with go pprof
# Fetching profile over HTTP from http://localhost:10005/debug/pprof/profile
# Saved profile in ${HOME}/pprof/pprof.samples.cpu.002.pb.gz
# Generating report in profile001.pb.gz

# 3. load pprof file, for example, using the built-in web UI

go tool pprof -http localhost:5000 $HOME/pprof/pprof.samples.cpu.001.pb.gz

Other kopia pprof endpoints: /debug/pprof/cmdline /debug/pprof/profile /debug/pprof/symbol /debug/pprof/trace

There are disadvantages to using the publish URL and poll vs. the method proposed in this PR train:

• Polling can miss state that is important to diagnosing some pod failures. The proposed method dumps pprof information on process exit, capturing state at process termination. Repeated pod terminations (by normal exits or failures) will create multiple dumps, removing guesswork of process lifecycle events (when debugging).
• Setting up network/tunnel to allow polling is "complicated". There are several hurdles to accessing published network ports depending on environment: tunnels and/or port forwarding may need to be setup, a destination for the captured files needs to be configured. In a Kubernetes environment this may mean configuration of additional services, containers, pods, volumes, etc... these changes present their own risks. The proposed method uses an existing, reliable, facility for capturing data - log capture. Many systems already have log capture facilities in the cluster or on the node, if not kubectl logs can be used to capture the output. This removes any new subsystems for file capture by using tools known to already have a high level of reliability and fidelity.
• The output from the proposed system may be automated with little support infrastructure. The process is limited to capturing log information. Conversion from PEM to binary form can be done off-line. As already mentioned, developing an automated system for capturing pprof data using published network endpoints will be complicated by network access and delineation of process lifecycle.
• This same facility is already a supported subsystem in other software. Having this implemented in Kopia gives the ability to capture pprof data across the entire application stack (not just export of snapshots).

[julio-lopez]

@aaron-kasten I see your point. It makes sense.

[codecov]

Codecov Report

All modified and coverable lines are covered by tests ✅

Comparison is base (ae72724) 75.85% compared to head (7577f7f) 75.84%.
Report is 1 commits behind head on master.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #3454      +/-   ##
==========================================
- Coverage   75.85%   75.84%   -0.02%     
==========================================
  Files         465      465              
  Lines       37166    37166              
==========================================
- Hits        28193    28188       -5     
- Misses       7047     7048       +1     
- Partials     1926     1930       +4     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[Shrekster]

LGTM!

[julio-lopez]

No request for immediate changes.

@aaron-kasten There are a number of inline questions, PTAL.

Merging as is, we can come back and iterate.

[julio-lopez]

Should KopiaDebugFlagForceGc be a "global" flag that applies to all profiles?
or

Should runtime.GC() be only called once even if multiple profiles specify the flag?

Thoughts?

[aaron-kasten]

I wanted to ensure that GC was run immediately before any memory profiling. This will allow users to check for memory leaks. There's a chance that other operations in the loop will allocate additional memory that I did not want to show up on the profile.

I did not want to special case which profiles allowed GC because PPROF dumps can be added by users - and there's no determining which profiles will benefit from an immediate GC. I could not conceive a scenario where only one GC would be required to produce accurate results.

[julio-lopez]

Asking because it is not clear to me whether a GC is needed before dumping each profile, or what difference it makes. To be clear, I don't have a good answer.

When stopping and dumping the profiles, it seems that a possible sequence would be

GC -> dump profile 1 -> GC -> dump profile 2 -> GC -> dump profile 3

In this case profile 2 would contain some information (allocations or side effects) coming from performing dump profile 1. Similarly, profile 3 would contain information coming from dumping profiles 1 and 2.

An alternative sequence would be.

GC -> dump profile 1, dump profile 2 -> dump profile 3

Not sure if it would make a difference, or if it matters.

[julio-lopez]

Anyway 🤷🏼‍♂️