0

I've been trying to profile my go application (evm-specification-miner) with pprof, but the output is not really useful:

(pprof) top5
108.59mins of 109.29mins total (99.36%)
Dropped 607 nodes (cum <= 0.55mins)
Showing top 5 nodes out of 103 (cum >= 0.98mins)
      flat  flat%   sum%        cum   cum%
  107.83mins 98.66% 98.66% 108.64mins 99.40%  [evm-specification-miner]
  0.36mins  0.33% 98.99%      6mins  5.49%  net.dialIP
  0.30mins  0.28% 99.27%   4.18mins  3.83%  net.listenIP
  0.06mins 0.052% 99.32%  34.66mins 31.71%  
github.com/urfave/cli.BoolFlag.ApplyWithError
  0.04mins 0.036% 99.36%   0.98mins   0.9%  net.probeIPv6Stack

And here is the cumulative output:

(pprof) top5 --cum
1.80hrs of 1.82hrs total (98.66%)
Dropped 607 nodes (cum <= 0.01hrs)
Showing top 5 nodes out of 103 (cum >= 1.53hrs)
      flat  flat%   sum%        cum   cum%
   1.80hrs 98.66% 98.66%    1.81hrs 99.40%  [evm-specification-miner]
         0     0% 98.66%    1.53hrs 83.93%  net.IP.matchAddrFamily
         0     0% 98.66%    1.53hrs 83.92%  net.(*UDPConn).WriteToUDP
         0     0% 98.66%    1.53hrs 83.90%  net.sockaddrToUDP
         0     0% 98.66%    1.53hrs 83.89%  net.(*UDPConn).readMsg

As you can see, most of the time is spent in evm-specification-miner (which is the name of my go application), but I've been unable to obtain more details or even understand what these square brackets meant (there is a question with a similar problem, but it didn't receive any answer).

Here are the build and pprof commands:

go install evm-specification-miner
go tool pprof evm-specification-miner cpuprof

I've even tried the debug flags -gcflags "-N -l" (as noted here: https://golang.org/doc/gdb#Introduction), to no avail.

The profiling is done with calls to pprof.StartCPUProfile() and pprof.StopCPUProfile() as is explained by this blog post: https://blog.golang.org/profiling-go-programs:

func StartProfiling(cpuprof string) error {
    f, err := os.Create(cpuprof)
    if err != nil {
        return err
    }
    return pprof.StartCPUProfile(f)
}

func StopProfiling() error {
    pprof.StopCPUProfile()
    return nil
}

StartProfiling is called at the beginning of main(), and StopProfiling when a signal (interrupt or kill) is received (or if the program terminates normally). This profile was obtained after an interruption.

Kegnarok
  • 1
  • 3
  • 1
    What is "evm-specification-miner"? Is it possible that your program just doesn't spend much time in Go functions? What does the cumulative output look like? – JimB Jul 25 '17 at 17:03
  • `evm-specification-miner` is the name of my go application. I've edited my question to add the cumulative output. I'm not sure about what you call go functions, but it is highly unlikely that my program spends most of its time waiting for a goroutine or anything else. – Kegnarok Jul 26 '17 at 08:11
  • By Go functions, I mean code written in Go. Does your code call into any C libraries or have any functionality implemented in assembly? Does it spend most of its time waiting for network? What do you expect to see in the profile? Can you share the code, or at least the part that creates the profile? – JimB Jul 26 '17 at 13:42
  • I use a library which itself calls C code. I wouldn't be surprised if the code spent most of its time in there, which might be the reason why I have this pprof output. I don't wait for the network, it is just a parallel thing I forgot to disable. I expect to see the name of my functions in the profile, such as: `1.0hrs 15.12% 27.45% ... main.main` I've edited my post with the exact code used to generate the profile. – Kegnarok Jul 26 '17 at 14:49
  • If the bulk of time is in C code, then there's not going to be much to see in the profile. I'm not sure offhand why you have `[evm-specification-miner]` rather than something like `main.main` or `package._Cfunc...`, but the output looks as I would expect otherwise. Are you using the latest Go release? – JimB Jul 26 '17 at 15:02
  • I'm using go1.7.4, but I'll try with go1.8.3 and edit if it the profile is different. – Kegnarok Jul 26 '17 at 15:13
  • Try with the go1.9 rc while you're at it. There were some changes to pprof in there too. – JimB Jul 26 '17 at 15:15

1 Answers1

0

Looks like updating to 1.9rc1 fixed it.

I no longer have [evm-specifiation-miner] in the profile (for the record, the top functions do not even come from my own package, so it is even weirder than they did not appear before).

BSMP
  • 4,596
  • 8
  • 33
  • 44
Kegnarok
  • 1
  • 3