How to do "frame" based profiling in GO?

[michael...@gmail.com]

Hello,

I'm trying to figure out how to do "frame" based profiling in GO and was redirect to this mailing--list from the `r/golang` sub (topic). Would be amazing if anyone here can help.

In short: I have a game server in Go and need to profile CPU costs of individual frames but sadly can't find a way to do that properly. 

I thought that the `pprof` CPU profile should be the right tool. However, at least the profile visualization tools always aggregate the methods execution costs between `StartCPUProfile` and `StopCPUProfile`. While in some scenarios this is great, we have currently have big spikes in for frame duration and would love to see the difference in times per frame. Ideally in a flame-graph like visualization but grouped by frames. So we'd somehow need to mark the frame start/end and tell the visualization to use that.

Ideally, like the profiler in the Unity3D Editor does:

Unity3D Profiling - Per frame method execution times

I tried use `Start/StopCPUProfile` at the beginning and end of a frame to create an individual capture per frame. That's not ideal for comparison but should be good enough and simple in concept. Sadly the cost of `StartCPUProfile` is so high, we can't call that per frame.

Looking at the code, the the 100 millisecond sleep in `profileWriter` explains that it. So what we'd need is a way to mark the frame start/end somehow for visual grouping. Is that possible with `pprof`?

pprof.go

Further, I wonder if it's even possible to profile a game server with a simulation framerate of 120Hz. Since the 100Hz CPU profile rate is hard coded in `StartCPUProfile` I would guess we even per frame aggregation it make not work of a frame duration is usually below 1s / 120 or is that not relevant?

Best,
 Michael

[Robert Engels]

You want to use pprof “labels” and mark the frames. 

On Jun 26, 2020, at 1:35 PM, michael...@gmail.com wrote:



--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/d0e8b1ae-d992-44ed-bd9a-6a72e6526d4co%40googlegroups.com.

[Michael Nischt]

Hi, thanks for the quick reply.

I tried that but I fear I don't really understand the API/tools for that.

What I did was wrapping the update function called every frame like that:

func profUpdate(update func(time.Duration), frame *uint64) func(time.Duration) {
  return func(time.Duration) {
    frameID := *frame
    *frame++
    labels := pprof.Labels("frame", fmt.Sprintf("%v", frameID))
    pprof.Do(context.Background(), labels, func(ctx context.Context) {
      update(dT)
    })
  }
}

Maybe the background context is the problem but after running the server for 1 minute only three tags are listed for frames 998, 1724 and 1967:

go tool pprof -tags logs/game-server.prof
frame: Total 30.0ms
             10.0ms (33.33%): 1724
             10.0ms (33.33%): 1967
             10.0ms (33.33%): 998

and there appearance in the graph is not really helpful either: https://i.imgur.com/eo9qgfv.png

Even if it had all frames, wouldn't each function call would have each frame label instead of splitting the graph by frames, right?
(at least it looks like that in this example: https://rakyll.org/profiler-labels/ - and each function with let's say 100 frame labels would already be impossible to read I fear).

Further, the labels don't even appear in the flame graph. let alone having it sliced by frame.

I really hope it's just that I simply don't understand how to use the API. 

However, I'm somewhat afraid frame based profiling is not really a common use case in GO and there's not good way to do it without writing an own solution.

Best,
 Michael