Refactor pprof labels and process desc (#32909)

* Deprecate "gopid" in log, it is not useful and requires very hacky
approach
* Remove "git.Command.SetDescription" because it is not useful and only
makes the logs too flexible

Author: wxiaoguang

modules/git/batch_reader.go

@@ -7,10 +7,8 @@ import (
 	"bufio"
 	"bytes"
 	"context"
-	"fmt"
 	"io"
 	"math"
-	"runtime"
 	"strconv"
 	"strings"
 
@@ -32,7 +30,6 @@ type WriteCloserError interface {
 func ensureValidGitRepository(ctx context.Context, repoPath string) error {
 	stderr := strings.Builder{}
 	err := NewCommand(ctx, "rev-parse").
-		SetDescription(fmt.Sprintf("%s rev-parse [repo_path: %s]", GitExecutable, repoPath)).
 		Run(&RunOpts{
 			Dir:    repoPath,
 			Stderr: &stderr,
@@ -62,13 +59,9 @@ func catFileBatchCheck(ctx context.Context, repoPath string) (WriteCloserError,
 		cancel()
 	}()
 
-	_, filename, line, _ := runtime.Caller(2)
-	filename = strings.TrimPrefix(filename, callerPrefix)
-
 	go func() {
 		stderr := strings.Builder{}
 		err := NewCommand(ctx, "cat-file", "--batch-check").
-			SetDescription(fmt.Sprintf("%s cat-file --batch-check [repo_path: %s] (%s:%d)", GitExecutable, repoPath, filename, line)).
 			Run(&RunOpts{
 				Dir:    repoPath,
 				Stdin:  batchStdinReader,
@@ -114,13 +107,9 @@ func catFileBatch(ctx context.Context, repoPath string) (WriteCloserError, *bufi
 		cancel()
 	}()
 
-	_, filename, line, _ := runtime.Caller(2)
-	filename = strings.TrimPrefix(filename, callerPrefix)
-
 	go func() {
 		stderr := strings.Builder{}
 		err := NewCommand(ctx, "cat-file", "--batch").
-			SetDescription(fmt.Sprintf("%s cat-file --batch [repo_path: %s] (%s:%d)", GitExecutable, repoPath, filename, line)).
 			Run(&RunOpts{
 				Dir:    repoPath,
 				Stdin:  batchStdinReader,
@@ -320,13 +309,6 @@ func ParseTreeLine(objectFormat ObjectFormat, rd *bufio.Reader, modeBuf, fnameBu
 	return mode, fname, sha, n, err
 }
 
-var callerPrefix string
-
-func init() {
-	_, filename, _, _ := runtime.Caller(0)
-	callerPrefix = strings.TrimSuffix(filename, "modules/git/batch_reader.go")
-}
-
 func DiscardFull(rd *bufio.Reader, discard int64) error {
 	if discard > math.MaxInt32 {
 		n, err := rd.Discard(math.MaxInt32)

modules/git/blame.go

@@ -7,7 +7,6 @@ import (
 	"bufio"
 	"bytes"
 	"context"
-	"fmt"
 	"io"
 	"os"
 
@@ -142,9 +141,7 @@ func CreateBlameReader(ctx context.Context, objectFormat ObjectFormat, repoPath
 		// There is no equivalent on Windows. May be implemented if Gitea uses an external git backend.
 		cmd.AddOptionValues("--ignore-revs-file", *ignoreRevsFile)
 	}
-	cmd.AddDynamicArguments(commit.ID.String()).
-		AddDashesAndList(file).
-		SetDescription(fmt.Sprintf("GetBlame [repo_path: %s]", repoPath))
+	cmd.AddDynamicArguments(commit.ID.String()).AddDashesAndList(file)
 	reader, stdout, err := os.Pipe()
 	if err != nil {
 		if ignoreRevsFile != nil {

modules/git/command.go

@@ -12,6 +12,7 @@ import (
 	"io"
 	"os"
 	"os/exec"
+	"path/filepath"
 	"runtime"
 	"strings"
 	"time"
@@ -43,18 +44,24 @@ type Command struct {
 	prog             string
 	args             []string
 	parentContext    context.Context
-	desc             string
 	globalArgsLength int
 	brokenArgs       []string
 }
 
-func (c *Command) String() string {
-	return c.toString(false)
+func logArgSanitize(arg string) string {
+	if strings.Contains(arg, "://") && strings.Contains(arg, "@") {
+		return util.SanitizeCredentialURLs(arg)
+	} else if filepath.IsAbs(arg) {
+		base := filepath.Base(arg)
+		dir := filepath.Dir(arg)
+		return filepath.Join(filepath.Base(dir), base)
+	}
+	return arg
 }
 
-func (c *Command) toString(sanitizing bool) string {
+func (c *Command) LogString() string {
 	// WARNING: this function is for debugging purposes only. It's much better than old code (which only joins args with space),
-	// It's impossible to make a simple and 100% correct implementation of argument quoting for different platforms.
+	// It's impossible to make a simple and 100% correct implementation of argument quoting for different platforms here.
 	debugQuote := func(s string) string {
 		if strings.ContainsAny(s, " `'\"\t\r\n") {
 			return fmt.Sprintf("%q", s)
@@ -63,12 +70,11 @@ func (c *Command) toString(sanitizing bool) string {
 	}
 	a := make([]string, 0, len(c.args)+1)
 	a = append(a, debugQuote(c.prog))
-	for _, arg := range c.args {
-		if sanitizing && (strings.Contains(arg, "://") && strings.Contains(arg, "@")) {
-			a = append(a, debugQuote(util.SanitizeCredentialURLs(arg)))
-		} else {
-			a = append(a, debugQuote(arg))
-		}
+	if c.globalArgsLength > 0 {
+		a = append(a, "...global...")
+	}
+	for i := c.globalArgsLength; i < len(c.args); i++ {
+		a = append(a, debugQuote(logArgSanitize(c.args[i])))
 	}
 	return strings.Join(a, " ")
 }
@@ -112,12 +118,6 @@ func (c *Command) SetParentContext(ctx context.Context) *Command {
 	return c
 }
 
-// SetDescription sets the description for this command which be returned on c.String()
-func (c *Command) SetDescription(desc string) *Command {
-	c.desc = desc
-	return c
-}
-
 // isSafeArgumentValue checks if the argument is safe to be used as a value (not an option)
 func isSafeArgumentValue(s string) bool {
 	return s == "" || s[0] != '-'
@@ -271,8 +271,12 @@ var ErrBrokenCommand = errors.New("git command is broken")
 
 // Run runs the command with the RunOpts
 func (c *Command) Run(opts *RunOpts) error {
+	return c.run(1, opts)
+}
+
+func (c *Command) run(skip int, opts *RunOpts) error {
 	if len(c.brokenArgs) != 0 {
-		log.Error("git command is broken: %s, broken args: %s", c.String(), strings.Join(c.brokenArgs, " "))
+		log.Error("git command is broken: %s, broken args: %s", c.LogString(), strings.Join(c.brokenArgs, " "))
 		return ErrBrokenCommand
 	}
 	if opts == nil {
@@ -285,20 +289,14 @@ func (c *Command) Run(opts *RunOpts) error {
 		timeout = defaultCommandExecutionTimeout
 	}
 
-	if len(opts.Dir) == 0 {
-		log.Debug("git.Command.Run: %s", c)
-	} else {
-		log.Debug("git.Command.RunDir(%s): %s", opts.Dir, c)
-	}
-
-	desc := c.desc
-	if desc == "" {
-		if opts.Dir == "" {
-			desc = fmt.Sprintf("git: %s", c.toString(true))
-		} else {
-			desc = fmt.Sprintf("git(dir:%s): %s", opts.Dir, c.toString(true))
-		}
+	var desc string
+	callerInfo := util.CallerFuncName(1 /* util */ + 1 /* this */ + skip /* parent */)
+	if pos := strings.LastIndex(callerInfo, "/"); pos >= 0 {
+		callerInfo = callerInfo[pos+1:]
 	}
+	// these logs are for debugging purposes only, so no guarantee of correctness or stability
+	desc = fmt.Sprintf("git.Run(by:%s, repo:%s): %s", callerInfo, logArgSanitize(opts.Dir), c.LogString())
+	log.Debug("git.Command: %s", desc)
 
 	var ctx context.Context
 	var cancel context.CancelFunc
@@ -401,7 +399,7 @@ func IsErrorExitCode(err error, code int) bool {
 
 // RunStdString runs the command with options and returns stdout/stderr as string. and store stderr to returned error (err combined with stderr).
 func (c *Command) RunStdString(opts *RunOpts) (stdout, stderr string, runErr RunStdError) {
-	stdoutBytes, stderrBytes, err := c.RunStdBytes(opts)
+	stdoutBytes, stderrBytes, err := c.runStdBytes(opts)
 	stdout = util.UnsafeBytesToString(stdoutBytes)
 	stderr = util.UnsafeBytesToString(stderrBytes)
 	if err != nil {
@@ -413,6 +411,10 @@ func (c *Command) RunStdString(opts *RunOpts) (stdout, stderr string, runErr Run
 
 // RunStdBytes runs the command with options and returns stdout/stderr as bytes. and store stderr to returned error (err combined with stderr).
 func (c *Command) RunStdBytes(opts *RunOpts) (stdout, stderr []byte, runErr RunStdError) {
+	return c.runStdBytes(opts)
+}
+
+func (c *Command) runStdBytes(opts *RunOpts) (stdout, stderr []byte, runErr RunStdError) {
 	if opts == nil {
 		opts = &RunOpts{}
 	}
@@ -435,7 +437,7 @@ func (c *Command) RunStdBytes(opts *RunOpts) (stdout, stderr []byte, runErr RunS
 		PipelineFunc:      opts.PipelineFunc,
 	}
 
-	err := c.Run(newOpts)
+	err := c.run(2, newOpts)
 	stderr = stderrBuf.Bytes()
 	if err != nil {
 		return nil, stderr, &runStdError{err: err, stderr: util.UnsafeBytesToString(stderr)}

modules/git/command_test.go

@@ -55,8 +55,8 @@ func TestGitArgument(t *testing.T) {
 
 func TestCommandString(t *testing.T) {
 	cmd := NewCommandContextNoGlobals(context.Background(), "a", "-m msg", "it's a test", `say "hello"`)
-	assert.EqualValues(t, cmd.prog+` a "-m msg" "it's a test" "say \"hello\""`, cmd.String())
+	assert.EqualValues(t, cmd.prog+` a "-m msg" "it's a test" "say \"hello\""`, cmd.LogString())
 
-	cmd = NewCommandContextNoGlobals(context.Background(), "url: https://a:b@c/")
-	assert.EqualValues(t, cmd.prog+` "url: https://sanitized-credential@c/"`, cmd.toString(true))
+	cmd = NewCommandContextNoGlobals(context.Background(), "url: https://a:b@c/", "/root/dir-a/dir-b")
+	assert.EqualValues(t, cmd.prog+` "url: https://sanitized-credential@c/" dir-a/dir-b`, cmd.LogString())
 }

modules/git/repo.go

@@ -18,7 +18,6 @@ import (
 	"time"
 
 	"code.gitea.io/gitea/modules/proxy"
-	"code.gitea.io/gitea/modules/util"
 )
 
 // GPGSettings represents the default GPG settings for this repository
@@ -160,12 +159,6 @@ func CloneWithArgs(ctx context.Context, args TrustedCmdArgs, from, to string, op
 	}
 	cmd.AddDashesAndList(from, to)
 
-	if strings.Contains(from, "://") && strings.Contains(from, "@") {
-		cmd.SetDescription(fmt.Sprintf("clone branch %s from %s to %s (shared: %t, mirror: %t, depth: %d)", opts.Branch, util.SanitizeCredentialURLs(from), to, opts.Shared, opts.Mirror, opts.Depth))
-	} else {
-		cmd.SetDescription(fmt.Sprintf("clone branch %s from %s to %s (shared: %t, mirror: %t, depth: %d)", opts.Branch, from, to, opts.Shared, opts.Mirror, opts.Depth))
-	}
-
 	if opts.Timeout <= 0 {
 		opts.Timeout = -1
 	}
@@ -213,12 +206,6 @@ func Push(ctx context.Context, repoPath string, opts PushOptions) error {
 	}
 	cmd.AddDashesAndList(remoteBranchArgs...)
 
-	if strings.Contains(opts.Remote, "://") && strings.Contains(opts.Remote, "@") {
-		cmd.SetDescription(fmt.Sprintf("push branch %s to %s (force: %t, mirror: %t)", opts.Branch, util.SanitizeCredentialURLs(opts.Remote), opts.Force, opts.Mirror))
-	} else {
-		cmd.SetDescription(fmt.Sprintf("push branch %s to %s (force: %t, mirror: %t)", opts.Branch, opts.Remote, opts.Force, opts.Mirror))
-	}
-
 	stdout, stderr, err := cmd.RunStdString(&RunOpts{Env: opts.Env, Timeout: opts.Timeout, Dir: repoPath})
 	if err != nil {
 		if strings.Contains(stderr, "non-fast-forward") {

modules/graceful/manager.go

@@ -9,6 +9,7 @@ import (
 	"sync"
 	"time"
 
+	"code.gitea.io/gitea/modules/gtprof"
 	"code.gitea.io/gitea/modules/log"
 	"code.gitea.io/gitea/modules/process"
 	"code.gitea.io/gitea/modules/setting"
@@ -136,7 +137,7 @@ func (g *Manager) doShutdown() {
 	}
 	g.lock.Lock()
 	g.shutdownCtxCancel()
-	atShutdownCtx := pprof.WithLabels(g.hammerCtx, pprof.Labels(LifecyclePProfLabel, "post-shutdown"))
+	atShutdownCtx := pprof.WithLabels(g.hammerCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "post-shutdown"))
 	pprof.SetGoroutineLabels(atShutdownCtx)
 	for _, fn := range g.toRunAtShutdown {
 		go fn()
@@ -167,7 +168,7 @@ func (g *Manager) doHammerTime(d time.Duration) {
 	default:
 		log.Warn("Setting Hammer condition")
 		g.hammerCtxCancel()
-		atHammerCtx := pprof.WithLabels(g.terminateCtx, pprof.Labels(LifecyclePProfLabel, "post-hammer"))
+		atHammerCtx := pprof.WithLabels(g.terminateCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "post-hammer"))
 		pprof.SetGoroutineLabels(atHammerCtx)
 	}
 	g.lock.Unlock()
@@ -183,7 +184,7 @@ func (g *Manager) doTerminate() {
 	default:
 		log.Warn("Terminating")
 		g.terminateCtxCancel()
-		atTerminateCtx := pprof.WithLabels(g.managerCtx, pprof.Labels(LifecyclePProfLabel, "post-terminate"))
+		atTerminateCtx := pprof.WithLabels(g.managerCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "post-terminate"))
 		pprof.SetGoroutineLabels(atTerminateCtx)
 
 		for _, fn := range g.toRunAtTerminate {

modules/graceful/manager_common.go

@@ -8,6 +8,8 @@ import (
 	"runtime/pprof"
 	"sync"
 	"time"
+
+	"code.gitea.io/gitea/modules/gtprof"
 )
 
 // FIXME: it seems that there is a bug when using systemd Type=notify: the "Install Page" (INSTALL_LOCK=false) doesn't notify properly.
@@ -22,12 +24,6 @@ const (
 	watchdogMsg  systemdNotifyMsg = "WATCHDOG=1"
 )
 
-// LifecyclePProfLabel is a label marking manager lifecycle phase
-// Making it compliant with prometheus key regex https://prometheus.io/docs/concepts/data_model/#metric-names-and-labels
-// would enable someone interested to be able to to continuously gather profiles into pyroscope.
-// Other labels for pprof (in "modules/process" package) should also follow this rule.
-const LifecyclePProfLabel = "graceful_lifecycle"
-
 func statusMsg(msg string) systemdNotifyMsg {
 	return systemdNotifyMsg("STATUS=" + msg)
 }
@@ -71,10 +67,10 @@ func (g *Manager) prepare(ctx context.Context) {
 	g.hammerCtx, g.hammerCtxCancel = context.WithCancel(ctx)
 	g.managerCtx, g.managerCtxCancel = context.WithCancel(ctx)
 
-	g.terminateCtx = pprof.WithLabels(g.terminateCtx, pprof.Labels(LifecyclePProfLabel, "with-terminate"))
-	g.shutdownCtx = pprof.WithLabels(g.shutdownCtx, pprof.Labels(LifecyclePProfLabel, "with-shutdown"))
-	g.hammerCtx = pprof.WithLabels(g.hammerCtx, pprof.Labels(LifecyclePProfLabel, "with-hammer"))
-	g.managerCtx = pprof.WithLabels(g.managerCtx, pprof.Labels(LifecyclePProfLabel, "with-manager"))
+	g.terminateCtx = pprof.WithLabels(g.terminateCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "with-terminate"))
+	g.shutdownCtx = pprof.WithLabels(g.shutdownCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "with-shutdown"))
+	g.hammerCtx = pprof.WithLabels(g.hammerCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "with-hammer"))
+	g.managerCtx = pprof.WithLabels(g.managerCtx, pprof.Labels(gtprof.LabelGracefulLifecycle, "with-manager"))
 
 	if !g.setStateTransition(stateInit, stateRunning) {
 		panic("invalid graceful manager state: transition from init to running failed")

modules/gtprof/gtprof.go

@@ -0,0 +1,25 @@
+// Copyright 2024 The Gitea Authors. All rights reserved.
+// SPDX-License-Identifier: MIT
+
+package gtprof
+
+// This is a Gitea-specific profiling package,
+// the name is chosen to distinguish it from the standard pprof tool and "GNU gprof"
+
+// LabelGracefulLifecycle is a label marking manager lifecycle phase
+// Making it compliant with prometheus key regex https://prometheus.io/docs/concepts/data_model/#metric-names-and-labels
+// would enable someone interested to be able to continuously gather profiles into pyroscope.
+// Other labels for pprof should also follow this rule.
+const LabelGracefulLifecycle = "graceful_lifecycle"
+
+// LabelPid is a label set on goroutines that have a process attached
+const LabelPid = "pid"
+
+// LabelPpid is a label set on goroutines that have a process attached
+const LabelPpid = "ppid"
+
+// LabelProcessType is a label set on goroutines that have a process attached
+const LabelProcessType = "process_type"
+
+// LabelProcessDescription is a label set on goroutines that have a process attached
+const LabelProcessDescription = "process_description"