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 On Wed, Jan 12, 2022 at 4:20 PM robert engels <reng...@ix.netcom.com> wrote: > 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. > > On Jan 12, 2022, at 5:29 PM, Steve Roth <st...@rothskeller.net> wrote: > > 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 > > > On Wed, Jan 12, 2022 at 2:58 PM Ian Lance Taylor <i...@golang.org> wrote: > >> 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 >> > > -- > 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+unsubscr...@googlegroups.com. > To view this discussion on the web visit > https://groups.google.com/d/msgid/golang-nuts/CAAnpqKGzr4MNfnC4Tqam2NoOt9AJ4NKP_Hiarv5usaYQYG1iNw%40mail.gmail.com > <https://groups.google.com/d/msgid/golang-nuts/CAAnpqKGzr4MNfnC4Tqam2NoOt9AJ4NKP_Hiarv5usaYQYG1iNw%40mail.gmail.com?utm_medium=email&utm_source=footer> > . > > > -- 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+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/golang-nuts/CAAnpqKEG8Brwe1yHLdWzSX76rCCidybTR-PC4HBgWVKEi7CE7A%40mail.gmail.com.
