From d52d183020842bebac788842e4f72d238609517d Mon Sep 17 00:00:00 2001 From: Steven Allen Date: Wed, 21 Jul 2021 14:12:22 -0700 Subject: [PATCH] feat: add an "ipfs diag profile" command This should replace the "collect-profiles.sh" script and allow users to easily collect profiles. At the moment, it just dumps all profiles into a single zip file. It does this server-side so it's easy fetch them with curl. In the future, it would be nice to add: 1. Progress indicators (cpu profiles take 30 seconds). 2. An option to specify which profiles to collect. But we can handle that later. Unfortunately, this command doesn't produce symbolized svgs as I didn't want to depend on having a local go compiler. --- core/commands/diag.go | 5 +- core/commands/profile.go | 205 +++++++++++++++++++++++++++++++++ core/commands/sysdiag.go | 56 +++++---- docs/debug-guide.md | 4 +- test/sharness/t0152-profile.sh | 40 +++++++ 5 files changed, 283 insertions(+), 27 deletions(-) create mode 100644 core/commands/profile.go create mode 100755 test/sharness/t0152-profile.sh diff --git a/core/commands/diag.go b/core/commands/diag.go index d7ddb6dfd13..89b46381f1e 100644 --- a/core/commands/diag.go +++ b/core/commands/diag.go @@ -10,7 +10,8 @@ var DiagCmd = &cmds.Command{ }, Subcommands: map[string]*cmds.Command{ - "sys": sysDiagCmd, - "cmds": ActiveReqsCmd, + "sys": sysDiagCmd, + "cmds": ActiveReqsCmd, + "profile": sysProfileCmd, }, } diff --git a/core/commands/profile.go b/core/commands/profile.go new file mode 100644 index 00000000000..a6893d4eb81 --- /dev/null +++ b/core/commands/profile.go @@ -0,0 +1,205 @@ +package commands + +import ( + "archive/zip" + "context" + "encoding/json" + "fmt" + "io" + "os" + "runtime" + "runtime/pprof" + "strings" + "time" + + cmds "github.com/ipfs/go-ipfs-cmds" + "github.com/ipfs/go-ipfs/core" + "github.com/ipfs/go-ipfs/core/commands/cmdenv" + "github.com/ipfs/go-ipfs/core/commands/e" +) + +// time format that works in filenames on windows. +var timeFormat = strings.ReplaceAll(time.RFC3339, ":", "_") + +type profileResult struct { + File string +} + +const cpuProfileTimeOption = "cpu-profile-time" + +var sysProfileCmd = &cmds.Command{ + NoLocal: true, + Options: []cmds.Option{ + cmds.StringOption(outputOptionName, "o", "The path where the output should be stored."), + cmds.StringOption(cpuProfileTimeOption, "The amount of time spent profiling CPU usage.").WithDefault("30s"), + }, + Run: func(req *cmds.Request, res cmds.ResponseEmitter, env cmds.Environment) error { + cpuProfileTimeStr, _ := req.Options[cpuProfileTimeOption].(string) + cpuProfileTime, err := time.ParseDuration(cpuProfileTimeStr) + if err != nil { + return fmt.Errorf("failed to parse CPU profile duration %q: %w", cpuProfileTimeStr, err) + } + + nd, err := cmdenv.GetNode(env) + if err != nil { + return err + } + + r, w := io.Pipe() + go func() { + _ = w.CloseWithError(writeProfiles(req.Context, nd, cpuProfileTime, w)) + }() + return res.Emit(r) + }, + PostRun: cmds.PostRunMap{ + cmds.CLI: func(res cmds.Response, re cmds.ResponseEmitter) error { + v, err := res.Next() + if err != nil { + return err + } + + outReader, ok := v.(io.Reader) + if !ok { + return e.New(e.TypeErr(outReader, v)) + } + + outPath, _ := res.Request().Options[outputOptionName].(string) + if outPath == "" { + outPath = "ipfs-profile-" + time.Now().Format(timeFormat) + ".zip" + } + fi, err := os.Create(outPath) + if err != nil { + return err + } + defer fi.Close() + + _, err = io.Copy(fi, outReader) + if err != nil { + return err + } + return re.Emit(&profileResult{File: outPath}) + }, + }, + Encoders: cmds.EncoderMap{ + cmds.Text: cmds.MakeTypedEncoder(func(req *cmds.Request, w io.Writer, out *profileResult) error { + fmt.Fprintf(w, "Wrote profiles to: %s\n", out.File) + return nil + }), + }, +} + +func writeProfiles(ctx context.Context, nd *core.IpfsNode, cpuProfileTime time.Duration, w io.Writer) error { + archive := zip.NewWriter(w) + + // Take some profiles. + type profile struct { + name string + file string + debug int + } + + profiles := []profile{{ + name: "goroutine", + file: "goroutines.stacks", + debug: 2, + }, { + name: "goroutine", + file: "goroutines.pprof", + }, { + name: "heap", + file: "heap.pprof", + }} + + for _, profile := range profiles { + prof := pprof.Lookup(profile.name) + out, err := archive.Create(profile.file) + if err != nil { + return err + } + err = prof.WriteTo(out, profile.debug) + if err != nil { + return err + } + } + + // Take a CPU profile. + if cpuProfileTime != 0 { + out, err := archive.Create("cpu.pprof") + if err != nil { + return err + } + + err = writeCPUProfile(ctx, cpuProfileTime, out) + if err != nil { + return err + } + } + + // Collect info + { + out, err := archive.Create("sysinfo.json") + if err != nil { + return err + } + info, err := getInfo(nd) + if err != nil { + return err + } + err = json.NewEncoder(out).Encode(info) + if err != nil { + return err + } + } + + // Collect binary + if fi, err := openIPFSBinary(); err == nil { + fname := "ipfs" + if runtime.GOOS == "windows" { + fname += ".exe" + } + + out, err := archive.Create(fname) + if err != nil { + return err + } + + _, err = io.Copy(out, fi) + _ = fi.Close() + if err != nil { + return err + } + } + return archive.Close() +} + +func writeCPUProfile(ctx context.Context, d time.Duration, w io.Writer) error { + if err := pprof.StartCPUProfile(w); err != nil { + return err + } + defer pprof.StopCPUProfile() + + timer := time.NewTimer(d) + defer timer.Stop() + + select { + case <-timer.C: + case <-ctx.Done(): + return ctx.Err() + } + return nil +} + +func openIPFSBinary() (*os.File, error) { + if runtime.GOOS == "linux" { + pid := os.Getpid() + fi, err := os.Open(fmt.Sprintf("/proc/%d/exe", pid)) + if err == nil { + return fi, nil + } + } + path, err := os.Executable() + if err != nil { + return nil, err + } + return os.Open(path) +} diff --git a/core/commands/sysdiag.go b/core/commands/sysdiag.go index 050b61c1373..9ab2578b25f 100644 --- a/core/commands/sysdiag.go +++ b/core/commands/sysdiag.go @@ -6,6 +6,7 @@ import ( "runtime" version "github.com/ipfs/go-ipfs" + "github.com/ipfs/go-ipfs/core" cmdenv "github.com/ipfs/go-ipfs/core/commands/cmdenv" cmds "github.com/ipfs/go-ipfs-cmds" @@ -21,40 +22,49 @@ Prints out information about your computer to aid in easier debugging. `, }, Run: func(req *cmds.Request, res cmds.ResponseEmitter, env cmds.Environment) error { - info := make(map[string]interface{}) - err := runtimeInfo(info) + nd, err := cmdenv.GetNode(env) if err != nil { return err } - err = envVarInfo(info) + info, err := getInfo(nd) if err != nil { return err } + return cmds.EmitOnce(res, info) + }, +} - err = diskSpaceInfo(info) - if err != nil { - return err - } +func getInfo(nd *core.IpfsNode) (map[string]interface{}, error) { + info := make(map[string]interface{}) + err := runtimeInfo(info) + if err != nil { + return nil, err + } - err = memInfo(info) - if err != nil { - return err - } - nd, err := cmdenv.GetNode(env) - if err != nil { - return err - } + err = envVarInfo(info) + if err != nil { + return nil, err + } - err = netInfo(nd.IsOnline, info) - if err != nil { - return err - } + err = diskSpaceInfo(info) + if err != nil { + return nil, err + } - info["ipfs_version"] = version.CurrentVersionNumber - info["ipfs_commit"] = version.CurrentCommit - return cmds.EmitOnce(res, info) - }, + err = memInfo(info) + if err != nil { + return nil, err + } + + err = netInfo(nd.IsOnline, info) + if err != nil { + return nil, err + } + + info["ipfs_version"] = version.CurrentVersionNumber + info["ipfs_commit"] = version.CurrentCommit + return info, nil } func runtimeInfo(out map[string]interface{}) error { diff --git a/docs/debug-guide.md b/docs/debug-guide.md index 8eb6d96b74b..6bcd65308f6 100644 --- a/docs/debug-guide.md +++ b/docs/debug-guide.md @@ -15,8 +15,8 @@ When you see ipfs doing something (using lots of CPU, memory, or otherwise being weird), the first thing you want to do is gather all the relevant profiling information. -There's a script (`bin/collect-profiles.sh`) that will do this for you and -bundle the results up into a tarball, ready to be attached to a bug report. +There's a command (`ipfs diag profile`) that will do this for you and +bundle the results up into a zip file, ready to be attached to a bug report. If you feel intrepid, you can dump this information and investigate it yourself: diff --git a/test/sharness/t0152-profile.sh b/test/sharness/t0152-profile.sh new file mode 100755 index 00000000000..d42046f0343 --- /dev/null +++ b/test/sharness/t0152-profile.sh @@ -0,0 +1,40 @@ +#!/usr/bin/env bash +# +# Copyright (c) 2016 Jeromy Johnson +# MIT Licensed; see the LICENSE file in this repository. +# + +test_description="Test profile collection" + +. lib/test-lib.sh + +test_init_ipfs + +test_expect_success "profiling requires a running daemon" ' + test_must_fail ipfs diag profile +' + +test_launch_ipfs_daemon + +test_expect_success "test profiling" ' + ipfs diag profile --cpu-profile-time=1s > cmd_out +' + +test_expect_success "filename shows up in output" ' + grep -q "ipfs-profile" cmd_out > /dev/null +' + +test_expect_success "profile file created" ' + test -e "$(sed -n -e "s/.*\(ipfs-profile.*\.zip\)/\1/p" cmd_out)" +' + +test_expect_success "test profiling with -o (without CPU profiling)" ' + ipfs diag profile --cpu-profile-time=0 -o test-profile.zip +' + +test_expect_success "test that test-profile.zip exists" ' + test -e test-profile.zip +' + +test_kill_ipfs_daemon +test_done