Program spends lot of time in syscall.Syscall and has unusually high number of allocations from malg

[ancientlore]

I've been attempting to apply some of the great performance tuning
suggestions from the blog post on profiling (http://blog.golang.org/
2011/06/profiling-go-programs.html) to an application I wrote. The
application uses multiple goroutines to read thousands of files and
uses the http client library to post these files to a web server.

I noticed two things in the profile. The first is that the program
spends a *lot* of time (80%) in syscall.Syscall, which I assume is
because it's reading a lot of data from files and transmitting it over
HTTP. I am curious if there is much to optimize when so much of the
time is in system calls. Would this be considered a normal result for
such a program?

The second issue I see is in the memory profile. The program has a
huge number of allocations from runtime.malg, which I believe is used
when creating a goroutine. My program code itself creates less than
200 goroutines that live for the life of the program. However, there
are over 25,000 allocations from malg. I read another post where Rob
indicated that a program with so many malg allocations could be
"leaking" goroutines, but at program exit or at any given time it has
less than 200. (The post is at
http://groups.google.com/group/golang-nuts/browse_thread/thread/3bfbb83dd9a15242/b2a2f3daffcbf2bf?lnk=gst&q=malg#b2a2f3daffcbf2bf)

So my question is - does the http package, for instance, create a
goroutine every time you use http.NewRequest and post that data to a
web server? If so, what causes those goroutines to be cleaned up?

Thanks for any insight.

[Russ Cox]

There should never be more 'g' structures than
there are active goroutines during the life of the
program. However, even if your program doesn't
create more than 200 goroutines it is possible
that something else is creating them (a library
you are using, for example).

The best way to figure out where they are coming
from is to look at the 'gv' or 'web' view, which will
show the call stack (as graph arrows) leading to
malg.

Russ

[ancientlore]

Thanks - I did that, and it seemed like nearly all the malg calls
traced up to crosscall_amd64(). Is there a way to see it beyond that?
(Like, am I missing something obvious?)

[Ian Lance Taylor]

ancientlore <michae...@gmail.com> writes:

> Thanks - I did that, and it seemed like nearly all the malg calls
> traced up to crosscall_amd64(). Is there a way to see it beyond that?
> (Like, am I missing something obvious?)

That will be the start of the goroutine for a program that uses cgo. It
is likely that there is nothing beyond that. The only case in which
there would be would be if you have Go code which calls C which calls
back into Go code.

Ian

[ancientlore]

I will do some more research Monday. This is just a regular 6g-
compiled pure Go program using standard packages plus two third-party
packages that don't use cgo. Maybe I am missing something about the
memory profiling, but since the http package creates goroutines I am
not surprised that a lot are created through the life of the program,
which makes thousands of http requests. I am just surprised at the
accumulation of allocations.

On Sep 30, 12:20 pm, Ian Lance Taylor <i...@google.com> wrote:

[ancientlore]

So here's a little example. This program just fetches 42 web pages in
parallel using 42 goroutines.

http://dl.dropbox.com/u/19269207/myhttp.go
http://dl.dropbox.com/u/19269207/cpu.svg
http://dl.dropbox.com/u/19269207/mem.svg
http://dl.dropbox.com/u/19269207/mem_inuse_objects.svg

If you look at the mem_inuse_objects version, I have 187,245 objects
associated with malg. I feel like I must be missing something pretty
basic about gopprof or how go uses malg().

Thanks for any thoughts.

[Dave Cheney]

pkg/net is partially implemented in cgo on Linux/Darwin/FreeBSD, could
that be where you're crosscall_$GOARCH calls be coming from ?

[Dmitry Vyukov]

On Mon, Oct 3, 2011 at 4:23 AM, ancientlore <michae...@gmail.com> wrote:

So here's a little example. This program just fetches 42 web pages in
parallel using 42 goroutines.

http://dl.dropbox.com/u/19269207/myhttp.go
http://dl.dropbox.com/u/19269207/cpu.svg
http://dl.dropbox.com/u/19269207/mem.svg
http://dl.dropbox.com/u/19269207/mem_inuse_objects.svg

If you look at the mem_inuse_objects version, I have 187,245 objects
associated with malg.

Probably it is 187,245 bytes associated with malg.

[ancientlore]

I'm pretty sure (but not positive) that it's objects because I used
the -inuse_objects option, and the svg says "objects". I was
definitely wondering if the http library used cgo somewhere, but even
if it did the number of objects seems a little high.

On Oct 2, 9:06 pm, Dmitry Vyukov <dvyu...@google.com> wrote:

[ancientlore]

So assuming that the net package uses cgo and creates goroutines,
would these goroutines show up in the count returned by
runtime.Goroutines()?

[Dmitry Vyukov]

On Thu, Oct 6, 2011 at 3:03 AM, ancientlore <michae...@gmail.com> wrote:

So assuming that the net package uses cgo and creates goroutines,
would these goroutines show up in the count returned by
runtime.Goroutines()?

Yes. 

[Russ Cox]

> I noticed two things in the profile. The first is that the program
> spends a *lot* of time (80%) in syscall.Syscall, which I assume is
> because it's reading a lot of data from files and transmitting it over
> HTTP. I am curious if there is much to optimize when so much of the
> time is in system calls. Would this be considered a normal result for
> such a program?

The profile at http://dl.dropbox.com/u/19269207/cpu.svg looks
more like 10% in Syscall, which seems fine. You are doing
a lot of system calls.

> The second issue I see is in the memory profile. The program has a
> huge number of allocations from runtime.malg, which I believe is used
> when creating a goroutine. My program code itself creates less than
> 200 goroutines that live for the life of the program. However, there
> are over 25,000 allocations from malg. I read another post where Rob
> indicated that a program with so many malg allocations could be
> "leaking" goroutines, but at program exit or at any given time it has
> less than 200.

Thanks for pointing this out.
This is a bug in the memory profiler, which I will fix.
It overcounts malg allocations by about 5000x.

Russ

[ancientlore]

Thanks so much, I feel like my sanity has returned.

I posted a different program that I could share because it was much
smaller and exhibited many of the same issues. The original cpu
profile with a lot of time in syscall is at:

http://dl.dropbox.com/u/19269207/ap.svg

I still think it's probably fine, because it's doing an awful lot of
IO. In fact that's mostly what the program is for. I was mainly
looking for opportunities to cut down on the CPU usage.

Mike

[Russ Cox]

The syscall.Syscall time there is because you have

lots of goroutines all gating onto a single OS thread

when they return from their system calls.

If you bump GOMAXPROCS higher you should

see this contention disappear.

Russ

[jup...@vividcortex.com]

I'm curious if this is still the case. We're seeing 50%+ in syscall.Syscall in a program, and we don't know what to make of it.

--Up.

[Dave Cheney]

Could you please start a new thread and post the .svg of your profile. 

--
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.
For more options, visit https://groups.google.com/groups/opt_out.