profiling tcp network server, time spent in syscall and mach_semaphore_wait

[Thomas Holloway]

I've been building a simple tcp server with a simple protocol to read off bytes, numbers, strings..etc similar to redis. I've been doing some profiling and it looks like most of the time is spent in syscall.System and mach_semaphore_wait. I don't know if there is any more optimizations that I can make, but I've included the output of the cpu profile below.

(pprof) top20 -cum

Total: 143 samples

       0   0.0%   0.0%      123  86.0% System

      94  65.7%  65.7%       94  65.7% runtime.mach_semaphore_wait

      29  20.3%  86.0%       29  20.3% runtime.kevent

       0   0.0%  86.0%       19  13.3% runtime.gosched0

      14   9.8%  95.8%       15  10.5% syscall.Syscall

       0   0.0%  95.8%       10   7.0% github.com/nyxtom/broadcast/server.(*BroadcastServer).handle

       0   0.0%  95.8%       10   7.0% github.com/nyxtom/broadcast/server.func·003

       0   0.0%  95.8%        9   6.3% bufio.(*Reader).ReadSlice

       0   0.0%  95.8%        9   6.3% github.com/nyxtom/broadcast/server.(*BroadcastServer).runClient

       0   0.0%  95.8%        9   6.3% github.com/nyxtom/broadcast/server.(*BufferClient).Read

       0   0.0%  95.8%        9   6.3% github.com/nyxtom/broadcast/server.(*BufferClient).readLine

       0   0.0%  95.8%        8   5.6% bufio.(*Reader).fill

       0   0.0%  95.8%        8   5.6% net.(*conn).Read

       0   0.0%  95.8%        8   5.6% net.(*netFD).Read

       0   0.0%  95.8%        8   5.6% syscall.Read

       0   0.0%  95.8%        8   5.6% syscall.read

       0   0.0%  95.8%        7   4.9% bufio.(*Writer).Flush

       0   0.0%  95.8%        7   4.9% bufio.(*Writer).flush

       0   0.0%  95.8%        7   4.9% github.com/nyxtom/broadcast/server.(*BufferClient).Flush

       0   0.0%  95.8%        7   4.9% net.(*conn).Write

Any help interpreting where I can focus my efforts?

[Thomas Holloway]

Here is another profile output:

[Thomas Holloway]

And the output for the above second output:

(pprof) top20 -cum

Total: 697 samples

       0   0.0%   0.0%      602  86.4% System

     505  72.5%  72.5%      505  72.5% runtime.mach_semaphore_wait

       0   0.0%  72.5%       90  12.9% runtime.gosched0

      82  11.8%  84.2%       82  11.8% runtime.kevent

      56   8.0%  92.3%       58   8.3% syscall.Syscall

       0   0.0%  92.3%       45   6.5% github.com/nyxtom/broadcast/server.(*BroadcastServer).runClient

       0   0.0%  92.3%       44   6.3% github.com/nyxtom/broadcast/server.(*BroadcastServer).handle

       0   0.0%  92.3%       44   6.3% github.com/nyxtom/broadcast/server.func·003

       0   0.0%  92.3%       38   5.5% github.com/nyxtom/broadcast/server.(*BufferClient).Read

       1   0.1%  92.4%       37   5.3% bufio.(*Writer).Flush

       0   0.0%  92.4%       37   5.3% github.com/nyxtom/broadcast/server.(*BufferClient).Flush

       0   0.0%  92.4%       36   5.2% bufio.(*Writer).flush

       0   0.0%  92.4%       36   5.2% net.(*conn).Write

       0   0.0%  92.4%       36   5.2% net.(*netFD).Write

       0   0.0%  92.4%       36   5.2% syscall.Write

       1   0.1%  92.5%       36   5.2% syscall.write

       0   0.0%  92.5%       34   4.9% bufio.(*Reader).ReadSlice

       0   0.0%  92.5%       34   4.9% github.com/nyxtom/broadcast/server.(*BufferClient).readLine

       0   0.0%  92.5%       27   3.9% bufio.(*Reader).fill

       0   0.0%  92.5%       27   3.9% net.(*conn).Read

[James Bardin]

Profiling doesn't really work on Darwin.

rsc had a binary patch to make it work, but I'm not sure of the current usability

http://research.swtch.com/macpprof

[James Bardin]

On Tuesday, August 26, 2014 2:53:07 PM UTC-4, James Bardin wrote:

Profiling doesn't really work on Darwin.

rsc had a binary patch to make it work, but I'm not sure of the current usability

http://research.swtch.com/macpprof

Ah, the comments in the code here seem to indicate it's still working (there was a buggy version at one point)

http://godoc.org/code.google.com/p/rsc/cmd/pprof_mac_fix