fgprof icon indicating copy to clipboard operation
fgprof copied to clipboard

fgprof skipping my functions, just showing useless graph

Open karelbilek opened this issue 2 years ago • 8 comments

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.

Screenshot 2023-04-11 at 10 10 05

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

karelbilek avatar Apr 11 '23 08:04 karelbilek

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

Why not to click on them to expand them?

cristaloleg avatar Apr 11 '23 08:04 cristaloleg

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 avatar Apr 11 '23 09:04 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 avatar Apr 11 '23 09:04 karelbilek

It seems the http2client.Reader is from GRPC.

karelbilek avatar Apr 11 '23 09:04 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 avatar Apr 11 '23 09:04 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 avatar Apr 11 '23 09:04 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)

karelbilek avatar Apr 11 '23 09:04 karelbilek

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.

felixge avatar Apr 19 '23 06:04 felixge

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

karelbilek avatar May 02 '24 11:05 karelbilek