fgprof skipping my functions, just showing useless graph

[karelbilek]

I used to use fgprof in the past, it showed me real time well.

However, now, it is "skipping" my functions, and I just see this.

This is useless. I know that there is a slow http request, but I don't see which ones because it skips my functions.

Pprof is working on the same codebase.

I am using go 1.19.7, I cannot move to 1.20. I tried to update indirect pprof dependency here too with no result

[cristaloleg]

By "skipping" you mean that you don't see function names and only colourful squares?

Why not to click on them to expand them?

[karelbilek]

No, I mean that it's not showing what is actually calling those functions and where is the time spent, just showing the http readers.

I see http2Client.Reader, but reading the http request is actually called by a function in main.go. So it's spending the time in the function in main, and in the handlers, but I don't see it there.

I see in the readme as an example

        // Http request to a web service that might be slow.
        slowNetworkRequest()

however I don't see slowNetworkRequest() equivalent function in the graph, I just see http2Client.Reader which catches all requests I am ever calling.

[karelbilek]

I want to see what is in the example here

https://github.com/felixge/fgprof/raw/master/assets/pprof_trace.png

that is, I want to see it under main. Not under http2client.Reader

[karelbilek]

It seems the http2client.Reader is from GRPC.

[karelbilek]

I don't see any functions defined in main in the graph. I just see the GRPC transport-related functions directly under runtime.goexit.

That's what I mean by "skipping". I don't see my functions, so I still need to do this :(

One way to decide which of these three functions you should focus your attention on would be to wrap each function call like this:

start := time.Start()
slowNetworkRequest()
fmt.Printf("slowNetworkRequest: %s\n", time.Since(start))
// ...

However, this can be very tedious for large programs.

[karelbilek]

I see pprof actually behaves the same, sorry. So it seems to not be a fgprof issue...? I don't know. But I am back to adding time.Since :(

[karelbilek]

I will try to replicate it with a small example, but that's not that easy haha (as GRPC is a monster to set up)

[felixge]

I think the problem you're seeing is caused by goroutines. When you start a new goroutine, the stack of the parent goroutine is not associated with it, so your stack traces start with the function after the go statement.

That being said, your functions should still be in the profile. I suspect they're just too small, so you need to use the flame graph filtering functions to search for your functions.

[karelbilek]

I have no idea how was this even done so I am closing this. I also used fgtrace successfully