High CPU usage in syscall.Syscall

[Vadim Tkachenko]

Hi,

I play with a small benchmark program and  I see go binary take significant CPU usage,

and profiling shows (if I read it correctly) it comes from syscall.Syscall, I wonder if there is way to eliminate this.

Profile is

(pprof) top -cum 20

23.74s of 66.90s total (35.49%)

Dropped 223 nodes (cum <= 0.33s)

Showing top 20 nodes out of 78 (cum >= 4.74s)

      flat  flat%   sum%        cum   cum%

         0     0%     0%     46.13s 68.95%  runtime.goexit

     0.17s  0.25%  0.25%     36.31s 54.28%  main.bummer

     0.12s  0.18%  0.43%     35.99s 53.80%  gopkg.in/mgo%2ev2.(*Collection).Insert

     0.28s  0.42%  0.85%     35.77s 53.47%  gopkg.in/mgo%2ev2.(*Collection).writeQuery

     0.98s  1.46%  2.32%     25.75s 38.49%  gopkg.in/mgo%2ev2.(*mongoSocket).Query

    20.11s 30.06% 32.38%     21.11s 31.55%  syscall.Syscall

     0.05s 0.075% 32.45%     17.45s 26.08%  net.(*conn).Write

     0.08s  0.12% 32.57%     17.40s 26.01%  net.(*netFD).Write

     0.03s 0.045% 32.62%     16.75s 25.04%  syscall.Write

     0.03s 0.045% 32.66%     16.72s 24.99%  syscall.write

         0     0% 32.66%     15.08s 22.54%  System

     0.49s  0.73% 33.39%      9.81s 14.66%  gopkg.in/mgo%2ev2.(*mongoSocket).readLoop

     0.14s  0.21% 33.60%      7.46s 11.15%  gopkg.in/mgo.v2/bson.Unmarshal

     0.12s  0.18% 33.78%      6.95s 10.39%  gopkg.in/mgo%2ev2.fill

     0.08s  0.12% 33.90%      6.77s 10.12%  net.(*conn).Read

     0.60s   0.9% 34.80%      6.73s 10.06%  gopkg.in/mgo.v2/bson.(*decoder).readDocTo

     0.33s  0.49% 35.29%      6.69s 10.00%  net.(*netFD).Read

         0     0% 35.29%      5.66s  8.46%  GC

     0.04s  0.06% 35.35%      4.78s  7.14%  syscall.Read

     0.09s  0.13% 35.49%      4.74s  7.09%  syscall.read

and the source is

https://play.golang.org/p/wVKPd2jWRN

[James Bardin]

On Tuesday, April 7, 2015 at 11:37:34 AM UTC-4, Vadim Tkachenko wrote:

Hi,

I play with a small benchmark program and  I see go binary take significant CPU usage,

and profiling shows (if I read it correctly) it comes from syscall.Syscall, I wonder if there is way to eliminate this.

The profile shows time spent in functions, not really CPU consumed. What you see is that most of your time writing to the database connection.

Also, what does your high CPU usage look like? I would expect this to show up mostly as iowait. 

[Vadim Tkachenko]

There is vmstat 5
vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
8 0 0 2813984 53836 909776 0 0 0 2 5686 258059
36 38 26 0 0
8 0 0 2811992 53836 911728 0 0 0 2 5620 231246
34 34 32 0 0
10 0 0 2810040 53836 913676 0 0 0 2301 5596 261074
37 37 26 0 0
10 0 0 2807932 53836 915516 0 0 0 2 5479 239067
36 39 25 0 0
8 0 0 2805924 53836 917540 0 0 0 2 5935 238852
42 37 21 0 0
9 0 0 2803816 53836 919464 0 0 0 3 5732 256004
38 37 25 0 0
12 0 0 2801704 53836 921444 0 0 0 3 5671 239615
33 39 28 0 0
7 0 0 2799844 53836 923436 0 0 0 3 5838 241806
38 36 27 0 0
5 0 0 2794364 53836 928760 0 0 0 3211 5335 254925
41 40 19 0 0
0 2 0 2792504 53836 930524 0 0 0 2 5159 269497
37 40 22 0 0
11 0 0 2790520 53836 932388 0 0 0 3 5509 257610
33 36 27 5 0
5 1 0 2788628 53836 934120 0 0 0 2 5598 255812
36 39 25 0 0

As you see CPU time divided between user & system CPU. there is no IO wait.

> --
> You received this message because you are subscribed to a topic in the
> Google Groups "golang-nuts" group.
> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/golang-nuts/RDxEBgX4VcU/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to
> golang-nuts...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.



--
Vadim Tkachenko, CTO, Percona
Phone +1-925-400-7377, Skype: vadimtk153

Percona Cloud Tools - to make MySQL Performance Easy
https://clould.percona.com

[James Bardin]

On Tuesday, April 7, 2015 at 12:29:11 PM UTC-4, Vadim Tkachenko wrote:

There is vmstat 5
 vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 8  0      0 2813984  53836 909776    0    0     0     2 5686 258059
36 38 26  0  0

OK, it looks like io and the db are keeping up. 

The original question though is still answered by most of the time being spent writing to the connection, which entails a Syscall. That's why you see it dominate the profile, as well as show up as a significant portion of sys cpu time. The profile and vmstat look how I would expect them to.

[Naoki INADA]

FYI, iowait means waiting disk io, not network.

sys includes CPU time for system call, network protocol stack and NIC control.

idle includes time for waiting writing / reading from network.

[Dave Cheney]

250,000 context switches per second is several orders of magnitude larger than it should be, especially given the interrupts are barely 0.5% of that figure. That is where all your time is going, in scheduling overheads.

[James Bardin]

On Tue, Apr 7, 2015 at 3:54 PM, Dave Cheney <da...@cheney.net> wrote:

250,000 context switches per second is several orders of magnitude larger than it should be, especially given the interrupts are barely 0.5% of that figure. That is where all your time is going, in scheduling overheads.

Good point Dave. I was reading the wrong column for cs :/

Was that with the GOMAXPROCS=1? If so, does your performance improve with the number of test goroutines closer or equal to GOMAXPROCS?

On Tue, Apr 7, 2015 at 3:52 PM, Naoki INADA <songof...@gmail.com> wrote:

FYI, iowait means waiting disk io, not network.

sys includes CPU time for system call, network protocol stack and NIC control.

idle includes time for waiting writing / reading from network.

yes sorry, that's correct [brain hiccup]. 

[Vadim Tkachenko]

I tried both
GOMAXPROCS=1
and
GOMAXPROCS=runtime.NumCPU() (which actually is 2, this is a cloud instance)

with the same result.

Thanks,
Vadim

[Dave Cheney]

Is the db running in the same machine, maybe the high load is not coming from your go process, it is just sitting idle while something else consumes all the cpu time.

[Vadim Tkachenko]

Dave,

db is running on the same machine.
I am monitoring cpu per process from "top" and cpu time is qually
distributed between go and mongod processes (which is still too high
for go, I think)

Thanks,
Vadim

> --
> You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
> To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/RDxEBgX4VcU/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.