From 7af5cdd864ecf8cf325845cd17686a99dcc5f4b8 Mon Sep 17 00:00:00 2001 From: niklr Date: Thu, 15 Jul 2021 10:19:32 +0200 Subject: [PATCH] Update pprof module extension --- api/service/pprof/service.go | 87 +++++++++++++++++++------------ api/service/pprof/service_test.go | 2 +- cmd/harmony/config_migrations.go | 6 +-- cmd/harmony/default.go | 4 +- cmd/harmony/flags.go | 2 +- cmd/harmony/flags_test.go | 4 +- go.mod | 2 +- 7 files changed, 64 insertions(+), 43 deletions(-) diff --git a/api/service/pprof/service.go b/api/service/pprof/service.go index e9dd66d94..03794a15e 100644 --- a/api/service/pprof/service.go +++ b/api/service/pprof/service.go @@ -49,6 +49,7 @@ type Service struct { var ( initOnce sync.Once svc = &Service{} + cpuFile *os.File ) // NewService creates the new pprof service @@ -61,21 +62,21 @@ func NewService(cfg Config) *Service { func newService(cfg Config) *Service { if !cfg.Enabled { - utils.Logger().Info().Msg("Pprof service disabled...") + utils.Logger().Info().Msg("pprof service disabled...") return nil } - utils.Logger().Debug().Str("cfg", cfg.String()).Msg("Pprof") + utils.Logger().Debug().Str("cfg", cfg.String()).Msg("pprof") svc.config = cfg - if profiles, err := cfg.unpackProfilesIntoMap(); err != nil { - log.Fatal("Could not unpack pprof profiles into map") - } else { - svc.profiles = profiles + profiles, err := cfg.unpackProfilesIntoMap() + if err != nil { + log.Fatal("could not unpack pprof profiles into map") } + svc.profiles = profiles go func() { - utils.Logger().Info().Str("address", cfg.ListenAddr).Msg("Starting pprof HTTP service") + utils.Logger().Info().Str("address", cfg.ListenAddr).Msg("starting pprof HTTP service") http.ListenAndServe(cfg.ListenAddr, nil) }() @@ -93,8 +94,10 @@ func (s *Service) Start() error { return err } - if cpuProfile, ok := s.profiles[CPU]; ok { - go handleCpuProfile(cpuProfile, dir) + if _, ok := s.profiles[CPU]; ok { + // The nature of the pprof CPU profile is fundamentally different to the other profiles, because it streams output to a file during profiling. + // Thus it has to be started outside of the defined interval. + go restartCpuProfile(dir) } for _, profile := range s.profiles { @@ -112,9 +115,12 @@ func (s *Service) Stop() error { } for _, profile := range s.profiles { if profile.Name == CPU { - pprof.StopCPUProfile() + stopCpuProfile() } else { - saveProfile(profile, dir) + err := saveProfile(profile, dir) + if err != nil { + utils.Logger().Error().Err(err).Msg(fmt.Sprintf("could not save pprof profile: %s", profile.Name)) + } } } return nil @@ -135,9 +141,15 @@ func scheduleProfile(profile Profile, dir string) { select { case <-ticker.C: if profile.Name == CPU { - handleCpuProfile(profile, dir) + err := restartCpuProfile(dir) + if err != nil { + utils.Logger().Error().Err(err).Msg("could not start pprof CPU profile") + } } else { - saveProfile(profile, dir) + err := saveProfile(profile, dir) + if err != nil { + utils.Logger().Error().Err(err).Msg(fmt.Sprintf("could not save pprof profile: %s", profile.Name)) + } } } } @@ -149,30 +161,39 @@ func scheduleProfile(profile Profile, dir string) { func saveProfile(profile Profile, dir string) error { f, err := newTempFile(dir, profile.Name, ".pb.gz") if err != nil { - utils.Logger().Error().Err(err).Msg(fmt.Sprintf("Could not save pprof profile: %s", profile.Name)) return err } defer f.Close() - if profile.ProfileRef != nil { - err = profile.ProfileRef.WriteTo(f, profile.Debug) - if err != nil { - utils.Logger().Error().Err(err).Msg(fmt.Sprintf("Could not write pprof profile: %s", profile.Name)) - return err - } - utils.Logger().Info().Msg(fmt.Sprintf("Saved pprof profile in: %s", f.Name())) + if profile.ProfileRef == nil { + return nil + } + err = profile.ProfileRef.WriteTo(f, profile.Debug) + if err != nil { + return err } + utils.Logger().Info().Msg(fmt.Sprintf("saved pprof profile in: %s", f.Name())) return nil } -// handleCpuProfile handles the provided CPU profile -func handleCpuProfile(profile Profile, dir string) { +// restartCpuProfile stops the current CPU profile, if any and then starts a new CPU profile. While profiling in the background, the profile will be buffered and written to a file. +func restartCpuProfile(dir string) error { + stopCpuProfile() + f, err := newTempFile(dir, CPU, ".pb.gz") + if err != nil { + return err + } + pprof.StartCPUProfile(f) + cpuFile = f + utils.Logger().Info().Msg(fmt.Sprintf("saved pprof CPU profile in: %s", f.Name())) + return nil +} + +// stopCpuProfile stops the current CPU profile, if any +func stopCpuProfile() { pprof.StopCPUProfile() - f, err := newTempFile(dir, profile.Name, ".pb.gz") - if err == nil { - pprof.StartCPUProfile(f) - utils.Logger().Info().Msg(fmt.Sprintf("Saved pprof CPU profile in: %s", f.Name())) - } else { - utils.Logger().Error().Err(err).Msg("Could not start pprof CPU profile") + if cpuFile != nil { + cpuFile.Close() + cpuFile = nil } } @@ -185,8 +206,8 @@ func (config *Config) unpackProfilesIntoMap() (map[string]Profile, error) { for index, name := range config.ProfileNames { profile := Profile{ Name: name, - Interval: 0, - Debug: 0, + Interval: 0, // 0 saves the profile when stopping the service + Debug: 0, // 0 writes the gzip-compressed protocol buffer } // Try set interval value if len(config.ProfileIntervals) == len(config.ProfileNames) { @@ -203,7 +224,7 @@ func (config *Config) unpackProfilesIntoMap() (map[string]Profile, error) { // Try set the profile reference if profile.Name != CPU { if p := pprof.Lookup(profile.Name); p == nil { - return nil, fmt.Errorf("Pprof profile does not exist: %s", profile.Name) + return nil, fmt.Errorf("pprof profile does not exist: %s", profile.Name) } else { profile.ProfileRef = p } @@ -219,7 +240,7 @@ func newTempFile(dir, name, suffix string) (*os.File, error) { currentTime := time.Now().Unix() f, err := os.OpenFile(filepath.Join(dir, fmt.Sprintf("%s%d%s", prefix, currentTime, suffix)), os.O_RDWR|os.O_CREATE|os.O_EXCL, 0666) if err != nil { - return nil, fmt.Errorf("Could not create file of the form %s%d%s", prefix, currentTime, suffix) + return nil, fmt.Errorf("could not create file of the form %s%d%s", prefix, currentTime, suffix) } return f, nil } diff --git a/api/service/pprof/service_test.go b/api/service/pprof/service_test.go index 31389ded5..b3977084a 100644 --- a/api/service/pprof/service_test.go +++ b/api/service/pprof/service_test.go @@ -37,7 +37,7 @@ func TestUnpackProfilesIntoMap(t *testing.T) { ProfileNames: []string{"test"}, }, expMap: nil, - expErr: errors.New("Pprof profile does not exist: test"), + expErr: errors.New("pprof profile does not exist: test"), }, { input: &Config{ diff --git a/cmd/harmony/config_migrations.go b/cmd/harmony/config_migrations.go index 3dc08a8d6..3a0a5676d 100644 --- a/cmd/harmony/config_migrations.go +++ b/cmd/harmony/config_migrations.go @@ -177,13 +177,13 @@ func init() { confTree.Set("Pprof.Folder", defaultConfig.Pprof.Folder) } if confTree.Get("Pprof.ProfileNames") == nil { - confTree.Set("Pprof.ProfileNames", make([]interface{}, 0)) + confTree.Set("Pprof.ProfileNames", defaultConfig.Pprof.ProfileNames) } if confTree.Get("Pprof.ProfileIntervals") == nil { - confTree.Set("Pprof.ProfileIntervals", make([]interface{}, 0)) + confTree.Set("Pprof.ProfileIntervals", defaultConfig.Pprof.ProfileIntervals) } if confTree.Get("Pprof.ProfileDebugValues") == nil { - confTree.Set("Pprof.ProfileDebugValues", make([]interface{}, 0)) + confTree.Set("Pprof.ProfileDebugValues", defaultConfig.Pprof.ProfileDebugValues) } confTree.Set("Version", "2.2.0") diff --git a/cmd/harmony/default.go b/cmd/harmony/default.go index b067bb377..395645f40 100644 --- a/cmd/harmony/default.go +++ b/cmd/harmony/default.go @@ -67,8 +67,8 @@ var defaultConfig = harmonyconfig.HarmonyConfig{ ListenAddr: "127.0.0.1:6060", Folder: "./profiles", ProfileNames: []string{}, - ProfileIntervals: []int{}, - ProfileDebugValues: []int{}, + ProfileIntervals: []int{600}, + ProfileDebugValues: []int{0}, }, Log: harmonyconfig.LogConfig{ Folder: "./latest", diff --git a/cmd/harmony/flags.go b/cmd/harmony/flags.go index abaf5de49..db249ec6c 100644 --- a/cmd/harmony/flags.go +++ b/cmd/harmony/flags.go @@ -986,7 +986,7 @@ var ( } pprofProfileDebugFlag = cli.IntSliceFlag{ Name: "pprof.profile.debug", - Usage: "a list of pprof profile debug integer values (separated by ,) e.g. 0 writes the gzip-compressed protocol buffer and 1 writes the legacy text format", + Usage: "a list of pprof profile debug integer values (separated by ,) e.g. 0 writes the gzip-compressed protocol buffer and 1 writes the legacy text format. Predefined profiles may assign meaning to other debug values: https://golang.org/pkg/runtime/pprof/", DefValue: defaultConfig.Pprof.ProfileDebugValues, Hidden: true, } diff --git a/cmd/harmony/flags_test.go b/cmd/harmony/flags_test.go index 343be93af..382ed9917 100644 --- a/cmd/harmony/flags_test.go +++ b/cmd/harmony/flags_test.go @@ -102,8 +102,8 @@ func TestHarmonyFlags(t *testing.T) { ListenAddr: "127.0.0.1:6060", Folder: "./profiles", ProfileNames: []string{}, - ProfileIntervals: []int{}, - ProfileDebugValues: []int{}, + ProfileIntervals: []int{600}, + ProfileDebugValues: []int{0}, }, Log: harmonyconfig.LogConfig{ Folder: "./latest", diff --git a/go.mod b/go.mod index 7f9c71a91..0c6159092 100644 --- a/go.mod +++ b/go.mod @@ -40,7 +40,7 @@ require ( github.com/multiformats/go-multiaddr-dns v0.3.1 github.com/natefinch/lumberjack v2.0.0+incompatible github.com/pborman/uuid v1.2.0 - github.com/pelletier/go-toml v1.2.0 + github.com/pelletier/go-toml v1.9.3 github.com/pkg/errors v0.9.1 github.com/prometheus/client_golang v1.8.0 github.com/rcrowley/go-metrics v0.0.0-20200313005456-10cdbea86bc0