From 3853ecf81f0eda550e31cd4a1cea59f1f2c2df00 Mon Sep 17 00:00:00 2001 From: Julio Lopez <1953782+julio-lopez@users.noreply.github.com> Date: Wed, 1 Oct 2025 15:30:30 -0700 Subject: [PATCH] chore(general): remove unused pproflogging package (#4850) --- internal/pproflogging/pproflogging.go | 445 --------------------- internal/pproflogging/pproflogging_test.go | 371 ----------------- 2 files changed, 816 deletions(-) delete mode 100644 internal/pproflogging/pproflogging.go delete mode 100644 internal/pproflogging/pproflogging_test.go diff --git a/internal/pproflogging/pproflogging.go b/internal/pproflogging/pproflogging.go deleted file mode 100644 index 182fc0168..000000000 --- a/internal/pproflogging/pproflogging.go +++ /dev/null @@ -1,445 +0,0 @@ -// Package pproflogging for pproflogging helper functions. -package pproflogging - -import ( - "bufio" - "bytes" - "context" - "encoding/pem" - "errors" - "fmt" - "io" - "os" - "runtime" - "runtime/pprof" - "strconv" - "strings" - "sync" - "time" - - "github.com/kopia/kopia/repo/logging" -) - -var log = logging.Module("kopia/pproflogging") - -// ProfileName the name of the profile (see: runtime/pprof/Lookup). -type ProfileName string - -const ( - pair = 2 - // PPROFDumpTimeout when dumping PPROF data, set an upper bound on the time it can take to log. - PPROFDumpTimeout = 15 * time.Second -) - -const ( - // DefaultDebugProfileRate default sample/data fraction for profile sample collection rates (1/x, where x is the - // data fraction sample rate). - DefaultDebugProfileRate = 100 - // DefaultDebugProfileDumpBufferSizeB default size of the pprof output buffer. - DefaultDebugProfileDumpBufferSizeB = 1 << 17 -) - -const ( - // EnvVarKopiaDebugPprof environment variable that contains the pprof dump configuration. - EnvVarKopiaDebugPprof = "KOPIA_PPROF_LOGGING_CONFIG" -) - -// flags used to configure profiling in EnvVarKopiaDebugPprof. -const ( - // KopiaDebugFlagForceGc force garbage collection before dumping heap data. - KopiaDebugFlagForceGc = "forcegc" - // KopiaDebugFlagDebug value of the profiles `debug` parameter. - KopiaDebugFlagDebug = "debug" - // KopiaDebugFlagRate rate setting for the named profile (if available). always an integer. - KopiaDebugFlagRate = "rate" -) - -const ( - // ProfileNameBlock block profile key. - ProfileNameBlock ProfileName = "block" - // ProfileNameMutex mutex profile key. - ProfileNameMutex = "mutex" - // ProfileNameCPU cpu profile key. - ProfileNameCPU = "cpu" -) - -var ( - // ErrEmptyProfileName returned when a profile configuration flag has no argument. - ErrEmptyProfileName = errors.New("empty profile flag") - - //nolint:gochecknoglobals - pprofConfigs = newProfileConfigs(os.Stderr) -) - -// Writer interface supports destination for PEM output. -type Writer interface { - io.Writer - io.StringWriter -} - -// ProfileConfigs configuration flags for all requested profiles. -type ProfileConfigs struct { - mu sync.Mutex - // wrt represents the final destination for the PPROF PEM output. Typically, - // this is attached to stderr or log output. A custom writer is used because - // not all loggers support line oriented output through the io.Writer interface... - // support is often attached th a io.StringWriter. - // +checklocks:mu - wrt Writer - // +checklocks:mu - pcm map[ProfileName]*ProfileConfig -} - -type pprofSetRate struct { - setter func(int) - defaultValue int -} - -//nolint:gochecknoglobals -var pprofProfileRates = map[ProfileName]pprofSetRate{ - ProfileNameBlock: { - setter: func(x int) { runtime.SetBlockProfileRate(x) }, - defaultValue: DefaultDebugProfileRate, - }, - ProfileNameMutex: { - setter: func(x int) { runtime.SetMutexProfileFraction(x) }, - defaultValue: DefaultDebugProfileRate, - }, -} - -func newProfileConfigs(wrt Writer) *ProfileConfigs { - q := &ProfileConfigs{ - wrt: wrt, - } - - return q -} - -// LoadProfileConfig configure PPROF profiling from the config in ppconfigss. -func LoadProfileConfig(ctx context.Context, ppconfigss string) (map[ProfileName]*ProfileConfig, error) { - // if empty, then don't bother configuring but emit a log message - user might be expecting them to be configured - if ppconfigss == "" { - log(ctx).Debug("no profile configuration. skipping PPROF setup") - return nil, nil - } - - bufSizeB := DefaultDebugProfileDumpBufferSizeB - - // look for matching services. "*" signals all services for profiling - log(ctx).Info("configuring profile buffers") - - // acquire global lock when performing operations with global side-effects - return parseProfileConfigs(bufSizeB, ppconfigss) -} - -// ProfileConfig configuration flags for a profile. -type ProfileConfig struct { - flags []string - buf *bytes.Buffer -} - -// GetValue get the value of the named flag, `s`. False will be returned -// if the flag does not exist. True will be returned if flag exists without -// a value. -func (p ProfileConfig) GetValue(s string) (string, bool) { - for _, f := range p.flags { - kvs := strings.SplitN(f, "=", pair) - if kvs[0] != s { - continue - } - - if len(kvs) == 1 { - return "", true - } - - return kvs[1], true - } - - return "", false -} - -func parseProfileConfigs(bufSizeB int, ppconfigs string) (map[ProfileName]*ProfileConfig, error) { - pbs := map[ProfileName]*ProfileConfig{} - allProfileOptions := strings.Split(ppconfigs, ":") - - for _, profileOptionWithFlags := range allProfileOptions { - // of those, see if any have profile specific settings - profileFlagNameValuePairs := strings.SplitN(profileOptionWithFlags, "=", pair) - flagValue := "" - - if len(profileFlagNameValuePairs) > 1 { - // only = allowed - flagValue = profileFlagNameValuePairs[1] - } - - flagKey := ProfileName(profileFlagNameValuePairs[0]) - if flagKey == "" { - return nil, ErrEmptyProfileName - } - - pbs[flagKey] = newProfileConfig(bufSizeB, flagValue) - } - - return pbs, nil -} - -// newProfileConfig create a new profiling configuration. -func newProfileConfig(bufSizeB int, ppconfig string) *ProfileConfig { - q := &ProfileConfig{ - buf: bytes.NewBuffer(make([]byte, 0, bufSizeB)), - } - - flgs := strings.Split(ppconfig, ",") - if len(flgs) > 0 && flgs[0] != "" { // len(flgs) > 1 && flgs[0] == "" should never happen - q.flags = flgs - } - - return q -} - -func setupProfileFractions(ctx context.Context, profileBuffers map[ProfileName]*ProfileConfig) { - for k, pprofset := range pprofProfileRates { - v, ok := profileBuffers[k] - if !ok { - // profile not configured - leave it alone - continue - } - - if v == nil { - // profile configured, but no rate - set to default - pprofset.setter(pprofset.defaultValue) - continue - } - - s, _ := v.GetValue(KopiaDebugFlagRate) - if s == "" { - // flag without an argument - set to default - pprofset.setter(pprofset.defaultValue) - continue - } - - n1, err := strconv.Atoi(s) - if err != nil { - log(ctx).With("cause", err).Warnf("invalid PPROF rate, %q, for '%s'", s, k) - continue - } - - log(ctx).Debugf("setting PPROF rate, %d, for %s", n1, k) - pprofset.setter(n1) - } -} - -// clearProfileFractions set the profile fractions to their zero values. -func clearProfileFractions(profileBuffers map[ProfileName]*ProfileConfig) { - for k, pprofset := range pprofProfileRates { - v := profileBuffers[k] - if v == nil { // fold missing values and empty values - continue - } - - _, ok := v.GetValue(KopiaDebugFlagRate) - if !ok { // only care if a value might have been set before - continue - } - - pprofset.setter(0) - } -} - -// StartProfileBuffers start profile buffers for enabled profiles/trace. Buffers -// are returned in an slice of buffers: CPU, Heap and trace respectively. class is used to distinguish profiles -// external to kopia. -func StartProfileBuffers(ctx context.Context) { - ppconfigs := os.Getenv(EnvVarKopiaDebugPprof) - // if empty, then don't bother configuring but emit a log message - use might be expecting them to be configured - if ppconfigs == "" { - log(ctx).Warn("no profile buffers enabled") - return - } - - bufSizeB := DefaultDebugProfileDumpBufferSizeB - - // look for matching services. "*" signals all services for profiling - log(ctx).Debug("configuring profile buffers") - - // acquire global lock when performing operations with global side-effects - pprofConfigs.mu.Lock() - defer pprofConfigs.mu.Unlock() - - var err error - - pprofConfigs.pcm, err = parseProfileConfigs(bufSizeB, ppconfigs) - if err != nil { - log(ctx).With("cause", err).Warnf("cannot start PPROF config, %q, due to parse error", ppconfigs) - return - } - - // profiling rates need to be set before starting profiling - setupProfileFractions(ctx, pprofConfigs.pcm) - - // cpu has special initialization - v, ok := pprofConfigs.pcm[ProfileNameCPU] - if ok { - err := pprof.StartCPUProfile(v.buf) - if err != nil { - log(ctx).With("cause", err).Warn("cannot start cpu PPROF") - delete(pprofConfigs.pcm, ProfileNameCPU) - } - } -} - -// DumpPem dump a PEM version of the byte slice, bs, into writer, wrt. -func DumpPem(bs []byte, types string, wrt *os.File) error { - // err0 for background process - var err0 error - - blk := &pem.Block{ - Type: types, - Bytes: bs, - } - // wrt is likely a line oriented writer, so writing individual lines - // will make best use of output buffer and help prevent overflows or - // stalls in the output path. - pr, pw := io.Pipe() - - // ensure read-end of the pipe is close - //nolint:errcheck - defer pr.Close() - - // encode PEM in the background and output in a line oriented - // fashion - this prevents the need for a large buffer to hold - // the encoded PEM. - go func() { - // writer close on exit of background process - // pipe writer will not return a meaningful error - //nolint:errcheck - defer pw.Close() - - // do the encoding - err0 = pem.Encode(pw, blk) - }() - - // connect rdr to pipe reader - rdr := bufio.NewReader(pr) - - // err1 for reading - // err2 for writing - var err1, err2 error - for err1 == nil && err2 == nil { - var ln []byte - ln, err1 = rdr.ReadBytes('\n') - // err1 can return ln and non-nil err1, so always call write - _, err2 = wrt.Write(ln) - } - - // got a write error. this has precedent - if err2 != nil { - return fmt.Errorf("could not write PEM: %w", err2) - } - - if err0 != nil { - return fmt.Errorf("could not write PEM: %w", err0) - } - - if err1 == nil { - return nil - } - - // if file does not end in newline, then output one - if errors.Is(err1, io.EOF) { - _, err2 = wrt.WriteString("\n") - if err2 != nil { - return fmt.Errorf("could not write PEM: %w", err2) - } - - return io.EOF - } - - return fmt.Errorf("error reading bytes: %w", err1) -} - -func parseDebugNumber(v *ProfileConfig) (int, error) { - debugs, ok := v.GetValue(KopiaDebugFlagDebug) - if !ok { - return 0, nil - } - - debug, err := strconv.Atoi(debugs) - if err != nil { - return 0, fmt.Errorf("could not parse number %q: %w", debugs, err) - } - - return debug, nil -} - -// StopProfileBuffers stop and dump the contents of the buffers to the log as PEMs. Buffers -// supplied here are from StartProfileBuffers. -func StopProfileBuffers(ctx context.Context) { - pprofConfigs.mu.Lock() - defer pprofConfigs.mu.Unlock() - - if pprofConfigs == nil { - log(ctx).Debug("profile buffers not configured") - return - } - - log(ctx).Debug("saving PEM buffers for output") - // cpu and heap profiles requires special handling - for k, v := range pprofConfigs.pcm { - log(ctx).Debugf("stopping PPROF profile %q", k) - - if v == nil { - continue - } - - if k == ProfileNameCPU { - pprof.StopCPUProfile() - continue - } - - _, ok := v.GetValue(KopiaDebugFlagForceGc) - if ok { - log(ctx).Debug("performing GC before PPROF dump ...") - runtime.GC() - } - - debug, err := parseDebugNumber(v) - if err != nil { - log(ctx).With("cause", err).Warn("invalid PPROF configuration debug number") - continue - } - - pent := pprof.Lookup(string(k)) - if pent == nil { - log(ctx).Warnf("no system PPROF entry for %q", k) - delete(pprofConfigs.pcm, k) - - continue - } - - err = pent.WriteTo(v.buf, debug) - if err != nil { - log(ctx).With("cause", err).Warn("error writing PPROF buffer") - - continue - } - } - // dump the profiles out into their respective PEMs - for k, v := range pprofConfigs.pcm { - if v == nil { - continue - } - - unm := strings.ToUpper(string(k)) - log(ctx).Infof("dumping PEM for %q", unm) - - err := DumpPem(v.buf.Bytes(), unm, os.Stderr) - if err != nil { - log(ctx).With("cause", err).Error("cannot write PEM") - } - } - - // clear the profile rates and fractions to effectively stop profiling - clearProfileFractions(pprofConfigs.pcm) - pprofConfigs.pcm = map[ProfileName]*ProfileConfig{} -} diff --git a/internal/pproflogging/pproflogging_test.go b/internal/pproflogging/pproflogging_test.go deleted file mode 100644 index 44ab703c9..000000000 --- a/internal/pproflogging/pproflogging_test.go +++ /dev/null @@ -1,371 +0,0 @@ -package pproflogging - -import ( - "bytes" - "context" - "fmt" - "io" - "maps" - "os" - "regexp" - "slices" - "testing" - - "github.com/stretchr/testify/require" - - "github.com/kopia/kopia/repo/logging" -) - -func TestDebug_StartProfileBuffers(t *testing.T) { - saveLockEnv(t) - // placeholder to make coverage happy - tcs := []struct { - in string - rx *regexp.Regexp - }{ - { - in: "", - rx: regexp.MustCompile("no profile buffers enabled"), - }, - { - in: ":", - rx: regexp.MustCompile(`cannot start PPROF config, ".*", due to parse error`), - }, - } - for _, tc := range tcs { - lg := &bytes.Buffer{} - ctx := logging.WithLogger(context.Background(), logging.ToWriter(lg)) - - t.Setenv(EnvVarKopiaDebugPprof, tc.in) - StartProfileBuffers(ctx) - require.Regexp(t, tc.rx, lg.String()) - } -} - -func TestDebug_parseProfileConfigs(t *testing.T) { - saveLockEnv(t) - - tcs := []struct { - in string - key ProfileName - expect []string - expectError error - expectMissing bool - n int - }{ - { - in: "foo", - key: "foo", - expect: nil, - n: 1, - }, - { - in: "foo=bar", - key: "foo", - expect: []string{ - "bar", - }, - n: 1, - }, - { - in: "first=one=1", - key: "first", - expect: []string{ - "one=1", - }, - n: 1, - }, - { - in: "foo=bar:first=one=1", - key: "first", - expect: []string{ - "one=1", - }, - n: 2, - }, - { - in: "foo=bar:first=one=1,two=2", - key: "first", - expect: []string{ - "one=1", - "two=2", - }, - n: 2, - }, - { - in: "foo=bar:first=one=1,two=2:second:third", - key: "first", - expect: []string{ - "one=1", - "two=2", - }, - n: 4, - }, - { - in: "foo=bar:first=one=1,two=2:second:third", - key: "foo", - expect: []string{ - "bar", - }, - n: 4, - }, - { - in: "foo=bar:first=one=1,two=2:second:third", - key: "second", - expect: nil, - n: 4, - }, - { - in: "foo=bar:first=one=1,two=2:second:third", - key: "third", - expect: nil, - n: 4, - }, - { - in: "=", - key: "", - expectMissing: true, - expectError: ErrEmptyProfileName, - }, - { - in: ":", - key: "", - expectMissing: true, - expectError: ErrEmptyProfileName, - }, - { - in: ",", - key: ",", - expect: nil, - n: 1, - }, - { - in: "=,:", - key: "", - expectMissing: true, - expectError: ErrEmptyProfileName, - }, - { - in: "", - key: "", - expectMissing: true, - expectError: ErrEmptyProfileName, - }, - { - in: ":=", - key: "cpu", - expectMissing: true, - expectError: ErrEmptyProfileName, - }, - } - for i, tc := range tcs { - t.Run(fmt.Sprintf("%d %s", i, tc.in), func(t *testing.T) { - pbs, err := parseProfileConfigs(1<<10, tc.in) - require.ErrorIs(t, tc.expectError, err) - require.Len(t, pbs, tc.n) - pb, ok := pbs[tc.key] // no negative testing for missing keys (see newProfileConfigs) - require.Equalf(t, !tc.expectMissing, ok, "key %q for set %q expect missing %t", tc.key, mapKeys(pbs), tc.expectMissing) - - if tc.expectMissing { - return - } - - require.Equal(t, 1<<10, pb.buf.Cap()) // bufsize is always 1024 - require.Equal(t, 0, pb.buf.Len()) - require.Equal(t, tc.expect, pb.flags) - }) - } -} - -func mapKeys[Map ~map[K]V, K comparable, V any](m Map) []K { - return slices.AppendSeq(make([]K, 0, len(m)), maps.Keys(m)) -} - -func TestDebug_newProfileConfigs(t *testing.T) { - saveLockEnv(t) - - tcs := []struct { - in string - key string - expect string - ok bool - }{ - { - in: "foo=bar", - key: "foo", - ok: true, - expect: "bar", - }, - { - in: "foo=", - key: "foo", - ok: true, - expect: "", - }, - { - in: "", - key: "foo", - ok: false, - expect: "", - }, - { - in: "foo=bar", - key: "bar", - ok: false, - expect: "", - }, - } - for i, tc := range tcs { - t.Run(fmt.Sprintf("%d %s", i, tc.in), func(t *testing.T) { - pb := newProfileConfig(1<<10, tc.in) - require.NotNil(t, pb) // always not nil - require.Equal(t, 1<<10, pb.buf.Cap()) // bufsize is always 1024 - v, ok := pb.GetValue(tc.key) - require.Equal(t, tc.ok, ok) - require.Equal(t, tc.expect, v) - }) - } -} - -func TestDebug_LoadProfileConfigs(t *testing.T) { - // save environment and restore after testing - saveLockEnv(t) - - ctx := context.Background() - - tcs := []struct { - inArgs string - profileKey ProfileName - profileFlagKey string - expectProfileFlagValue string - expectProfileFlagExists bool - expectConfigurationCount int - expectError error - expectProfileConfigNotExists bool - }{ - { - inArgs: "", - expectConfigurationCount: 0, - profileKey: "", - expectError: nil, - expectProfileConfigNotExists: true, - }, - { - inArgs: "block=rate=10:cpu:mutex=10", - expectConfigurationCount: 3, - profileKey: "block", - profileFlagKey: "rate", - expectProfileFlagExists: true, - expectProfileFlagValue: "10", - expectError: nil, - }, - { - inArgs: "block=rate=10:cpu:mutex=10", - expectConfigurationCount: 3, - profileKey: "cpu", - profileFlagKey: "rate", - expectProfileFlagExists: false, - }, - { - inArgs: "block=rate=10:cpu:mutex=10", - expectConfigurationCount: 3, - profileKey: "mutex", - profileFlagKey: "10", - expectProfileFlagExists: true, - }, - { - inArgs: "mutex=10", - expectConfigurationCount: 1, - profileKey: "cpu", - profileFlagKey: "10", - expectProfileConfigNotExists: true, - }, - } - - for i, tc := range tcs { - t.Run(fmt.Sprintf("%d: %q", i, tc.inArgs), func(t *testing.T) { - pmp, err := LoadProfileConfig(ctx, tc.inArgs) - require.ErrorIs(t, tc.expectError, err) - - if err != nil { - return - } - - val, ok := pmp[tc.profileKey] - require.Equalf(t, tc.expectProfileConfigNotExists, !ok, "expecting key %q to %t exist", tc.profileKey, !tc.expectProfileConfigNotExists) - - if tc.expectProfileConfigNotExists { - return - } - - flagValue, ok := val.GetValue(tc.profileFlagKey) - require.Equal(t, tc.expectProfileFlagExists, ok, "expecting key %q to %t exist", tc.profileKey, tc.expectProfileFlagExists) - - if tc.expectProfileFlagExists { - return - } - - require.Equal(t, tc.expectProfileFlagValue, flagValue) - }) - } -} - -//nolint:gocritic -func saveLockEnv(t *testing.T) { - t.Helper() - - oldEnv := os.Getenv(EnvVarKopiaDebugPprof) - - t.Cleanup(func() { - // restore the old environment - t.Setenv(EnvVarKopiaDebugPprof, oldEnv) - }) -} - -func TestErrorWriter(t *testing.T) { - eww := &ErrorWriter{mx: 5, err: io.EOF} - n, err := eww.WriteString("Hello World") - require.ErrorIs(t, io.EOF, err) - require.Equal(t, 5, n) - require.Equal(t, "Hello", string(eww.bs)) -} - -// ErrorWriter allows injection of errors into the write stream. There are a few -// failures in PPROF dumps that are worth modeling for tests ([io.EOF] is one) -// For use specify the error, ErrorWriter.err, and byte index, ErrorWriter.mx, -// in which it should occur. -type ErrorWriter struct { - bs []byte - mx int - err error -} - -func (p *ErrorWriter) Write(bs []byte) (int, error) { - n := len(bs) - - if len(bs)+len(p.bs) > p.mx { - // error will be produced at p.mx - // so don't return any more than - // n - n = p.mx - len(p.bs) - } - - // append the bytes to the local buffer just - // in case someone wants to know. - p.bs = append(p.bs, bs[:n]...) - if n < len(bs) { - // here we assume that any less than len(bs) - // bytes written returns an error. This - // allows setting ErrorWriter up once - // to produce an error after multiple - // writes - return n, p.err - } - - return n, nil -} - -//nolint:gocritic -func (p *ErrorWriter) WriteString(s string) (int, error) { - return p.Write([]byte(s)) -}