runtime/pprof: cpu profiling broken on OS X

[adg]

Running godoc on OS X 10.6.7 with the changes shown below, the CPU profile only lists
calls to __cgo_allocate. This has been reported on the list, too.


$ gopprof godoc godoc.prof
Welcome to pprof!  For help, type 'help'.
(pprof) top10
Total: 7200 samples
    7200 100.0% 100.0%     7200 100.0% __cgo_allocate



diff -r b295b8bda20b src/cmd/godoc/godoc.go
--- a/src/cmd/godoc/godoc.go    Sun Jun 26 11:24:28 2011 +1000
+++ b/src/cmd/godoc/godoc.go    Mon Jun 27 08:41:25 2011 +1000
@@ -20,6 +20,7 @@
    "path/filepath"
    "regexp"
    "runtime"
+   "runtime/pprof"
    "sort"
    "strings"
    "template"
@@ -1279,6 +1280,7 @@
            log.Printf("before GC: bytes = %d footprint = %d", runtime.MemStats.HeapAlloc, runtime.MemStats.Sys)
            runtime.GC()
            log.Printf("after  GC: bytes = %d footprint = %d", runtime.MemStats.HeapAlloc, runtime.MemStats.Sys)
+           pprof.StopCPUProfile()
        }
        var delay int64 = 60 * 1e9 // by default, try every 60s
        if *testDir != "" {
diff -r b295b8bda20b src/cmd/godoc/main.go
--- a/src/cmd/godoc/main.go Sun Jun 26 11:24:28 2011 +1000
+++ b/src/cmd/godoc/main.go Mon Jun 27 08:41:25 2011 +1000
@@ -39,6 +39,7 @@
    "path/filepath"
    "regexp"
    "runtime"
+   "runtime/pprof"
    "strings"
    "time"
 )
@@ -218,10 +219,21 @@
 }
 
 
+var cpuprofile = flag.String("cpuprofile", "", "")
+
 func main() {
    flag.Usage = usage
    flag.Parse()
 
+   if *cpuprofile != "" {
+       f, err := os.Create(*cpuprofile)
+       if err != nil {
+           log.Fatal(err)
+       }
+       pprof.StartCPUProfile(f)
+       defer pprof.StopCPUProfile()
+   }
+
    // Determine file system to use.
    // TODO(gri) Complete this - for now we only have one.
    fs = OS

[adg]

Comment 1:

Discussion:
https://groups.google.com/d/topic/golang-nuts/iHOklv2z-Sg/discussion

[rsc]

Comment 2:

As far as I can tell this is in Apple's hands.
CPU profiling only works in single-proc programs, but
pprof.StartCPUProfiling inherently starts a second proc
(blocked waiting for profiling data), and the cpu ticks
very often go there.
I don't expect this to be fixed any time soon but if
this is important to you and you have some way to
make that known to Apple, feel free.
Full Apple Bug Report below.
changeset:   7868:35b716c94225
user:        Russ Cox <rsc@golang.org>
date:        Fri Mar 25 13:47:07 2011 -0400
files:       src/pkg/runtime/pprof/pprof_test.go
description:
runtime/pprof: disable test on darwin
Fixes issue #1641.
Actually it side steps the real issue, which is that the
setitimer(2) implementation on OS X is not useful for
profiling of multi-threaded programs.  I filed the below
using the Apple Bug Reporter.
/*
Filed as Apple Bug Report #9177434.
This program creates a new pthread that loops, wasting cpu time.
In the main pthread, it sleeps on a condition that will never come true.
Before doing so it sets up an interval timer using ITIMER_PROF.
The handler prints a message saying which thread it is running on.
POSIX does not specify which thread should receive the signal, but
in order to be useful in a user-mode self-profiler like pprof or gprof
   http://code.google.com/p/google-perftools
   http://www.delorie.com/gnu/docs/binutils/gprof_25.html
it is important that the thread that receives the signal is the one
whose execution caused the timer to expire.
Linux and FreeBSD handle this by sending the signal to the process's
queue but delivering it to the current thread if possible:
   http://lxr.linux.no/linux+v2.6.38/kernel/signal.c#L802
     807        /*
     808         * Now find a thread we can wake up to take the signal off the queue.
     809         *
     810         * If the main thread wants the signal, it gets first crack.
     811         * Probably the least surprising to the average bear.
     812         * /
   http://fxr.watson.org/fxr/source/kern/kern_sig.c?v=FREEBSD8;im=bigexcerpts#L1907
     1914         /*
     1915          * Check if current thread can handle the signal without
     1916          * switching context to another thread.
     1917          * /
On those operating systems, this program prints:
    $ ./a.out
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    signal on cpu-chewing looper thread
    $
The OS X kernel does not have any such preference.  Its get_signalthread
does not prefer current_thread(), in contrast to the other two systems,
so the signal gets delivered to the first thread in the list that is able to
handle it, which ends up being the main thread in this experiment.
http://fxr.watson.org/fxr/source/bsd/kern/kern_sig.c?v=xnu-1456.1.26;im=excerpts#L1666
    $ ./a.out
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    signal on sleeping main thread
    $
The fix is to make get_signalthread use the same heuristic as
Linux and FreeBSD, namely to use current_thread() if possible
before scanning the process thread list.
*/
#include <sys/time.h>
#include <sys/signal.h>
#include <pthread.h>
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
static void handler(int);
static void* looper(void*);
static pthread_t pmain, ploop;
int
main(void)
{
        struct itimerval it;
        struct sigaction sa;
        pthread_cond_t cond;
        pthread_mutex_t mu;
        memset(&sa, 0, sizeof sa);
        sa.sa_handler = handler;
        sa.sa_flags = SA_RESTART;
        memset(&sa.sa_mask, 0xff, sizeof sa.sa_mask);
        sigaction(SIGPROF, &sa, 0);
        pmain = pthread_self();
        pthread_create(&ploop, 0, looper, 0);
        memset(&it, 0, sizeof it);
        it.it_interval.tv_usec = 10000;
        it.it_value = it.it_interval;
        setitimer(ITIMER_PROF, &it, 0);
        pthread_mutex_init(&mu, 0);
        pthread_mutex_lock(&mu);
        pthread_cond_init(&cond, 0);
        for(;;)
                pthread_cond_wait(&cond, &mu);
        return 0;
}
static void
handler(int sig)
{
        static int nsig;
        pthread_t p;
        p = pthread_self();
        if(p == pmain)
                printf("signal on sleeping main thread\n");
        else if(p == ploop)
                printf("signal on cpu-chewing looper thread\n");
        else
                printf("signal on %p\n", (void*)p);
        if(++nsig >= 10)
                exit(0);
}
static void*
looper(void *v)
{
        for(;;);
}
R=r
CC=golang-dev
http://golang.org/cl/4273113

Labels changed: added expertneeded.

Status changed to LongTerm.

[rsc]

Comment 3:

Labels changed: added priority-later.

[rsc]

Comment 4:

Labels changed: added priority-go1.

[robpike]

Comment 5:

Owner changed to builder@golang.org.

[rsc]

Comment 7:

This issue was closed by revision 6e2ae0a.

Status changed to Fixed.