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

doc: runtime/pprof: block profiler documentation needs some love #14689

Open
pwaller opened this Issue Mar 7, 2016 · 8 comments

Comments

Projects
None yet
10 participants
@pwaller
Contributor

pwaller commented Mar 7, 2016

Reading https://golang.org/pkg/runtime/pprof/ does not make clear how to use the blocking profiler in an application.

The blog post at http://blog.golang.org/profiling-go-programs (2011) finishes with:

The goroutine blocking profile will be explained in a future post. Stay tuned.

But I cannot find any follow up.

In a post to the mailing list someone said that Brad mentioned it briefly in a talk, but he only mentions go test -blockprofile, and I'm not running tests.

I have used several search engines to look for materials but they all point at runtime/pprof and other not-useful-to-me blog posts. Getting creative, I just thought I would dive in and try to use it:

    f, err := os.Create("block.pprof")
    if err != nil {
        log.Fatal(err)
    }
    p := pprof.Lookup("block")
    defer func() {
        err := p.WriteTo(f, 0)
        if err != nil {
            log.Fatalf("Error writing block profile: %v", err)
        }
    }()

Which results in a file with contents which don't look useful:

--- contention:
cycles/second=2494323129

Finally, I searched github for "pprof lookup block". This appears to show some examples of its use and reveals the function runtime.SetBlockProfile. However, this function is also quite confusingly documented.

func SetBlockProfileRate(rate int)

SetBlockProfileRate controls the fraction of goroutine blocking events that are reported in the blocking profile. The profiler aims to sample an average of one blocking event per rate nanoseconds spent blocked.

To include every blocking event in the profile, pass rate = 1. To turn off profiling entirely, pass rate <= 0.

Is rate really a fraction, between 0 and 1? If so, since it is an int, it would seem my options are to either pass it 0 or 1, but the suggestion that it is a fraction seems contradictory. Is it necessary to call this function to start the profiler?

To conclude, the documentation at runtime/pprof really needs to make it clear how to use the block profiler. Some facts which are still not clear to me, even after reading code found elsewhere:

  • What kind of questions can be answered with a block profile?
    • Will it help me identify contention on a channel write?
    • Will it tell me where in my program is contending?
  • How do I use the block profiler in my application?
  • Is there something one must do to start the block profiler?
  • How often can one write a block profile? Once at the end of a running program?
  • Why is there not a StartBlockProfiler function?
  • How does one interpret the results of a block profile?

P.S. I did eventually find Debugging performance issues in Go programs, which answers some of these questions. But unfortunately it was not easy to find for some reason.

@ianlancetaylor ianlancetaylor added this to the Go1.7 milestone Mar 7, 2016

@rhysh

This comment has been minimized.

Show comment
Hide comment
@rhysh

rhysh Mar 8, 2016

Contributor

runtime.SetBlockProfileRate has two special values: 0 to disable, and 1 to catch every single event. You can also set it to e.g. 1,000,000,000 (aka int(time.Second.Nanoseconds())) to record one sample per second that a goroutine is blocked at a particular location. If your program does not set the rate to something > 0, the block profile will contain no data.

What I'd be most interested to learn from a blog post on the blocking profiler is what to expect in terms of performance overhead. I've taken the fact that it's not enabled by default (compared with e.g. the heap profiler) to mean that it may have a significant impact on runtime performance. On the other hand, its instrumentation points seem to be a subset of what's covered by runtime/trace, which is automatically accessible via net/http/pprof. Dmitry Vyukov's article mentions that it interferes with the scheduler trace, which could be part of the answer.

Contributor

rhysh commented Mar 8, 2016

runtime.SetBlockProfileRate has two special values: 0 to disable, and 1 to catch every single event. You can also set it to e.g. 1,000,000,000 (aka int(time.Second.Nanoseconds())) to record one sample per second that a goroutine is blocked at a particular location. If your program does not set the rate to something > 0, the block profile will contain no data.

What I'd be most interested to learn from a blog post on the blocking profiler is what to expect in terms of performance overhead. I've taken the fact that it's not enabled by default (compared with e.g. the heap profiler) to mean that it may have a significant impact on runtime performance. On the other hand, its instrumentation points seem to be a subset of what's covered by runtime/trace, which is automatically accessible via net/http/pprof. Dmitry Vyukov's article mentions that it interferes with the scheduler trace, which could be part of the answer.

@pwaller

This comment has been minimized.

Show comment
Hide comment
@pwaller

pwaller Mar 8, 2016

Contributor

Thanks @rhysh, that clears up the units a little. I found this sentence is quite hard to read. With the example @rhysh gave of set it to 1G and it samples all blocked goroutines once per second and suddenly it's easy to read. Maybe an example would help?

The profiler aims to sample an average of one blocking event per rate nanoseconds spent blocked.

Contributor

pwaller commented Mar 8, 2016

Thanks @rhysh, that clears up the units a little. I found this sentence is quite hard to read. With the example @rhysh gave of set it to 1G and it samples all blocked goroutines once per second and suddenly it's easy to read. Maybe an example would help?

The profiler aims to sample an average of one blocking event per rate nanoseconds spent blocked.

@anacrolix

This comment has been minimized.

Show comment
Hide comment
@anacrolix

anacrolix Jan 12, 2017

Contributor

Any progress on this?

Contributor

anacrolix commented Jan 12, 2017

Any progress on this?

@bradfitz bradfitz modified the milestones: Go1.9, Unreleased Jan 12, 2017

@bradfitz bradfitz modified the milestones: Go1.9Maybe, Go1.9 Jun 13, 2017

@bradfitz

This comment has been minimized.

Show comment
Hide comment
@bradfitz

bradfitz Jun 13, 2017

Member

No progress on this. (Progress would be posted here, and nothing is posted here)

Help wanted.

Member

bradfitz commented Jun 13, 2017

No progress on this. (Progress would be posted here, and nothing is posted here)

Help wanted.

@whh8b

This comment has been minimized.

Show comment
Hide comment
@whh8b

whh8b Jul 3, 2017

I have reason to use this in a non-server context. I will attempt to provide/contribute some documentation but I can't make any guarantees that it will be interesting or useful. I will update here as I get information.

whh8b commented Jul 3, 2017

I have reason to use this in a non-server context. I will attempt to provide/contribute some documentation but I can't make any guarantees that it will be interesting or useful. I will update here as I get information.

@whh8b

This comment has been minimized.

Show comment
Hide comment
@whh8b

whh8b Jul 14, 2017

I would really like to add this function:

func WriteBlockProfile(w io.Writer) error {
    return writeBlock(w, 0)
}

to src/runtime/pprof/pprof.go. I think that would make the Block profile API more consistent with the memory and CPU profile APIs. I know that this is not the place to get code reviews, but I wanted to get everyone's gut reaction before I started with the gerrit code review, etc.

I have already integrated this into a few test applications and it works pretty well, actually.

I look forward to hearing your feedback!

Thanks!
Will

@bradfitz

whh8b commented Jul 14, 2017

I would really like to add this function:

func WriteBlockProfile(w io.Writer) error {
    return writeBlock(w, 0)
}

to src/runtime/pprof/pprof.go. I think that would make the Block profile API more consistent with the memory and CPU profile APIs. I know that this is not the place to get code reviews, but I wanted to get everyone's gut reaction before I started with the gerrit code review, etc.

I have already integrated this into a few test applications and it works pretty well, actually.

I look forward to hearing your feedback!

Thanks!
Will

@bradfitz

@bradfitz

This comment has been minimized.

Show comment
Hide comment
@bradfitz

bradfitz Jul 14, 2017

Member

@whh8b, it's too late to add anything new to Go 1.9. This CL is marked Go 1.9Maybe because it's a documentation-only change. To propose new API changes, open a new bug.

Member

bradfitz commented Jul 14, 2017

@whh8b, it's too late to add anything new to Go 1.9. This CL is marked Go 1.9Maybe because it's a documentation-only change. To propose new API changes, open a new bug.

@ianlancetaylor ianlancetaylor modified the milestones: Go1.10, Go1.9Maybe Aug 3, 2017

@rsc rsc modified the milestones: Go1.10, Go1.11 Dec 1, 2017

@gopherbot gopherbot modified the milestones: Go1.11, Unplanned May 23, 2018

@pwaller

This comment has been minimized.

Show comment
Hide comment
@pwaller

pwaller Sep 14, 2018

Contributor

Just came across a comment from @rsc on reddit about this:

We do believe that the blocking profiler does what it is advertised to do, because there are tests for it. That said, I have never found the profiles particularly useful, and maybe that's what you meant by "I get stuck". To me, the fundamental issue is that what you really want is to distinguish good blocking (like a goroutine waiting for the next network request; that time is not the application's fault) from bad blocking (like excessive delay due to mutex contention). It's difficult to do that without some knowledge of the application, although perhaps we could do better by having just a mutex contention profile; that would be most useful if all the other kinds of blocking are "good" for your program.

Contributor

pwaller commented Sep 14, 2018

Just came across a comment from @rsc on reddit about this:

We do believe that the blocking profiler does what it is advertised to do, because there are tests for it. That said, I have never found the profiles particularly useful, and maybe that's what you meant by "I get stuck". To me, the fundamental issue is that what you really want is to distinguish good blocking (like a goroutine waiting for the next network request; that time is not the application's fault) from bad blocking (like excessive delay due to mutex contention). It's difficult to do that without some knowledge of the application, although perhaps we could do better by having just a mutex contention profile; that would be most useful if all the other kinds of blocking are "good" for your program.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment