Google Groupes

Help understanding profiling data: runtime.mach_semaphore_signal


Giovanni Bajo 28 févr. 2016 10:20
Envoyé au groupe : golang-nuts
Hello,

I'm trying to profile an application I wrote, while running in specific situations in which I measure a slowdown which I don't understand how it is caused. I'm using Go 1.6 on OSX.

This is the output of top20:

(pprof) top20
3.39s of 3.57s total (94.96%)
Dropped 54 nodes (cum <= 0.02s)
Showing top 20 nodes out of 136 (cum >= 0.17s)
      flat  flat%   sum%        cum   cum%
     1.84s 51.54% 51.54%      1.84s 51.54%  runtime.mach_semaphore_signal
     0.59s 16.53% 68.07%      0.59s 16.53%  runtime.mach_semaphore_wait
     0.35s  9.80% 77.87%      0.35s  9.80%  runtime.usleep
     0.14s  3.92% 81.79%      0.14s  3.92%  runtime.cgocall
     0.09s  2.52% 84.31%      0.09s  2.52%  runtime.memclr
     0.05s  1.40% 85.71%      0.05s  1.40%  runtime.memmove
     0.04s  1.12% 86.83%      0.18s  5.04%  main.(*HwDmaChannel).xfer
     0.04s  1.12% 87.96%      0.05s  1.40%  ndsemu/raster3d.(*HwEngine3d).Draw3D
     0.04s  1.12% 89.08%      0.04s  1.12%  runtime.mach_semaphore_timedwait
     0.04s  1.12% 90.20%      0.04s  1.12%  runtime.scanobject
     0.03s  0.84% 91.04%      0.03s  0.84%  ndsemu/e2d.e2dMixer_Normal
     0.03s  0.84% 91.88%      0.03s  0.84%  runtime/internal/atomic.Xadd
     0.02s  0.56% 92.44%      0.12s  3.36%  runtime.lock
     0.02s  0.56% 93.00%      0.02s  0.56%  runtime.scanstack
     0.02s  0.56% 93.56%      0.02s  0.56%  runtime/internal/atomic.Load
     0.01s  0.28% 93.84%      0.10s  2.80%  main.(*HwGeometry).WriteGXFIFO
     0.01s  0.28% 94.12%      0.03s  0.84%  ndsemu/arm.(*Cpu).opRead32
     0.01s  0.28% 94.40%      0.16s  4.48%  ndsemu/arm.(*Cpu).opWrite32
     0.01s  0.28% 94.68%      0.07s  1.96%  ndsemu/e2d.(*HwEngine2d).DrawBGAffine
     0.01s  0.28% 94.96%      0.17s  4.76%  runtime.call32

I've also attached the SVG produced by "web runtime.mach_semaphore_signal". 

I'm at loss on how to parse this profile. It looks like 50% of execution time is spent within the runtime for some.. semaphore contention? I don't know. Also the callgraph shown in the SVG goes very deep within the runtime and I can't follow it.

Assuming there is some contention/lock between goroutines/channels or something like that, is there some other tool I could try that could give me a different picture that helps me spotting the problem? Or can anybody point me to any resource on how to analyze this kind of problems?

I can provide binary and profile dump to anybody willing to help (and it is an open source project anyway).

Giovanni Bajo