profiling help

[Steve Roth]

I am attempting to profile my code, and I'm unable to interpret the results.  So first, the meta-question is, what's the best forum to use to request help with such things?

The code I'm profiling is the server side of a moderately complex webapp.  For simplicity, I've wrapped it with net/http/cgi and am calling it from the command line as a CGI "script".  As such, it is handling a single request with no actual network traffic.  Also, I've disabled the garbage collector.  I'm calling pprof.StartCPUProfile at the top of ServeHTTP.  The pprof output is at

https://scholacantorum.org/pprof.svg

It shows three different call chains.  The one that actually includes my code, starting at runtime.main, is only 6% of the total CPU samples.  There are two other call chains that are entirely within the runtime package, one of them taking 17% of the time and the other taking a whopping 70% of the time, and I can't figure out what they're doing.  I would appreciate any guidance.

The chain that is taking 70% of the time is

gcBgMarkWorker

systemstack

gcBgMarkWorker.func2

gcDrain

markroot

markroot.func1

suspendG

Underneath suspendG it splits into nanotime, osyield, procyield, and preemptM, the latter of which has signalM, tgkill, and getpid children.  getpid alone is shown as taking 4% of the CPU of the entire program!  What the heck is this call chain doing, with nearly three quarters of my time?

The chain that is taking 17% of the time is

mcall

park_m

schedule

findrunnable

stopm

mPark

notesleep

futexsleep

futex

Again I have no clue what this is doing.  Any guidance is welcome, including pointers to other forums better suited for such questions.

Regards,

Steve

[Howard C. Shaw III]

The 17% is sleeping. The 70% is garbage collection.

[Ian Lance Taylor]

On Wed, Jan 12, 2022 at 1:54 PM Steve Roth <st...@rothskeller.net> wrote:
>
> I am attempting to profile my code, and I'm unable to interpret the results. So first, the meta-question is, what's the best forum to use to request help with such things?

This is a good place. See also https://golang.org/wiki/Questions.

> The chain that is taking 70% of the time is
>
> gcBgMarkWorker
>
> systemstack
>
> gcBgMarkWorker.func2
>
> gcDrain
>
> markroot
>
> markroot.func1
>
> suspendG

This is the concurrent garbage collector.

> The chain that is taking 17% of the time is
>
> mcall
>
> park_m
>
> schedule
>
> findrunnable
>
> stopm
>
> mPark
>
> notesleep
>
> futexsleep
>
> futex
>
> Again I have no clue what this is doing. Any guidance is welcome, including pointers to other forums better suited for such questions.

This is the goroutine scheduler.

If your program is CPU bound (as it should be based on your
description) then 70% in the garbage collector is a lot. The next
step is to collect a heap profile to see where the memory is being
allocated. You may want to look at https://go.dev/blog/pprof, old but
still valid.

Ian

[Steve Roth]

Thank you, Ian.  From the function names, I suspected that the 70% chain was the garbage collector.  But in this run, garbage collection was turned off with GOGC=off, and that was verified with GODEBUG=gctrace=1.  So I thought perhaps they must be something else.

I will proceed with heap profiling as you suggest.  (And of course I've reviewed pprof blog post many times.)

Regards,

Steve

[robert engels]

Are you certain that the requests aren’t super short - so all you are measuring is the runtime startup time / and the overhead of parsing the CGI “protocol". This is not insignificant. CGI really only works well for long requests IMO.

-- 
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.
To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAAnpqKGzr4MNfnC4Tqam2NoOt9AJ4NKP_Hiarv5usaYQYG1iNw%40mail.gmail.com.

[Steve Roth]

Hi, Robert,

The request *should* be super short, but it was actually taking 2.5 seconds.  That was the whole reason I started trying to profile it, to figure out why a simple request was taking so long.

Ian's suggestion of heap tracing found the issue for me:  there was an unexpected allocation of a 13MB block in there.  Tracing that, I found the root cause, which was corrupted data in my site database.  Many thanks to all for the help.

Regards,

Steve

[Kurtis Rader]

FWIW, I had the same suspicion as Robert. In my experience a CGI task that takes less than, say, 200ms is going to be swamped by startup costs. It's usually better to use the FastCGI protocol in that situation. 

To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAAnpqKEG8Brwe1yHLdWzSX76rCCidybTR-PC4HBgWVKEi7CE7A%40mail.gmail.com.

--

Kurtis Rader

Caretaker of the exceptional canines Junior and Hank

[Steve Roth]

Thanks, Kurtis,

The production version of this code runs as a regular web server.  I was profiling in CGI just to simplify the configuration.

Regards,

Steve