Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

proposal: runtime/pprof: add WriteGoroutineLabels function for logging #51223

Open
ansiwen opened this issue Feb 16, 2022 · 8 comments
Open

proposal: runtime/pprof: add WriteGoroutineLabels function for logging #51223

ansiwen opened this issue Feb 16, 2022 · 8 comments
Labels
Milestone

Comments

@ansiwen
Copy link

@ansiwen ansiwen commented Feb 16, 2022

Problem Statement

Given that goroutines are anonymous and there is no accessible goroutine id makes it very difficult to add goroutine context to debug/tracing output without having a context parameter in all functions and a context field in all objects, which is often unfeasible. That lead to many attempts to workaround this limitation and reoccurring debates about it. So, although beyond doubt there is a reasonable demand for context logging, it has deliberately been ignored in order to not undermine the anonymity of goroutines, which is regarded as more important.

Proposal

As a kind of compromise, that allows to log goroutine context, without making it too easy to abuse it for "goroutine local storage", I want to propose the following API:

package pprof

// WriteGoroutineLabels writes the current goroutine's labels to w. If a write
// to w returns an error, that error is returned, nil otherwise. The format of
// the output is not specified, and should only be used for logging/tracing
// purposes.
func WriteGoroutineLabels(w io.Writer) error { ... }

This would easily and efficiently allow to set labels with the SetGoroutineLabels() and Do() functions, and still log them in code paths, where the context is not available, and give important information for log forensics. This is especially useful for 3rd party libraries, that don't support contexts, but do support setting a global log sink for debug output. For example:

import (
  "context"
  "log"
  "runtime/pprof"

  "github.com/ansiwen/foobar"
)

func init() {
  foobar.SetDebugOutput(func(msg string) {
    var lbls strings.Builder
    _ = pprof.WriteGoroutineLabels(&lbls)
    log.Printf(`[DBG]<foobar> msg="%s" context="%s"`, msg, lbls.String())
  })
}

func fireFoobarRequest(id string, data []byte) {
  go func() {
    lbl := pprof.Labels("requestID", id)
    pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), lbl))
    foobar.doRequest(data)
  }()
}

Edit: added usage example.

@gopherbot gopherbot added this to the Proposal milestone Feb 16, 2022
@ianlancetaylor ianlancetaylor added this to Incoming in Proposals Feb 16, 2022
@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Feb 16, 2022

It seems like you are suggesting that there are packages out there that don't and won't take a context.Context, and that don't and won't take a logger that could annotate logs however it likes, but that will change their code to call pprof.WriteGoroutineLabels. Do you have any examples of packages like that?

@ansiwen
Copy link
Author

@ansiwen ansiwen commented Feb 16, 2022

@ianlancetaylor Thanks for your answer. No, sorry, I think I didn't make that clear enough. I'm talking about libraries, that don't support context.Context but do support setting a logger for debug output. Let me demonstrate it with some example code:

import (
  "context"
  "log"
  "runtime/pprof"

  "github.com/ansiwen/foobar"
)

func init() {
  foobar.SetDebugOutput(func(msg string) {
    var lbls strings.Builder
    _ = pprof.WriteGoroutineLabels(&lbls)
    log.Printf(`[DBG]<foobar> msg="%s" context="%s"`, msg, lbls.String())
  })
}

func fireFoobarRequest(id string, data []byte) {
  go func() {
    lbl := pprof.Labels("requestID", id)
    pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), lbl))
    foobar.doRequest(data)
  }()
}

(I just sketched that down, probably full of mistakes.) So it basically applies to all libraries that

  1. allow to set a logger or similar as a (global) debug sink
  2. doesn't take a context (or at least, doesn't make it available in the debug log callback) and
  3. that is potentially used concurrently.

Without this "tunneling" of context, it inevitably gets lost, and you can't relate the debug output to the request anymore.

I hope that makes it more clear.

Edit: fixed inconsistency in example

@ansiwen
Copy link
Author

@ansiwen ansiwen commented Feb 16, 2022

And regarding an example library: While I believe there are loads of libraries that fit into that category, we are about to add debug logging to our ceph Go bindings and realised, that without breaking our API the users can't relate the concurrent calls into the library with the debug output.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Feb 17, 2022

It seems to me that if you can pass in a logger, then you can create a logger type that attaches any information you like to the log. It can do the equivalent of pprof.WriteGoroutineLabels, only it doesn't need to call that function because it knows the relevant labels.

@ansiwen
Copy link
Author

@ansiwen ansiwen commented Feb 17, 2022

@ianlancetaylor How can it do that? Of course it could store any information, but a global logger instance, that is called from concurrent goroutines, could never know, which is the "right" information to add. The result of pprof.WriteGoroutineLabels is depending on the goroutine in which it is called, because every goroutine has its own set of labels.

@ansiwen
Copy link
Author

@ansiwen ansiwen commented Feb 18, 2022

Alternatively maybe this is also sufficient:

func GoroutineLabelsString() string { ... }

I was following the WriteTo scheme, but maybe in this case that's over-engineered, because the output is shorter.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Feb 18, 2022

Sorry, I meant that you pass in the logger appropriate to the goroutine. I didn't mean to imply that there was a single global logger.

@ansiwen
Copy link
Author

@ansiwen ansiwen commented Feb 18, 2022

I see. But libraries don't usually support passing in a logger per request, at least I've never seen that. Either you can pass in a global logger, or they use the standard logger, which output you can redirect. If the library offers a logger per request that is an equivalent of a context.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
Status: Todo
Proposals
Incoming
Development

No branches or pull requests

3 participants