Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime/pprof: cpu profiling broken on OS X #2008

Closed
adg opened this issue Jun 26, 2011 · 6 comments
Closed

runtime/pprof: cpu profiling broken on OS X #2008

adg opened this issue Jun 26, 2011 · 6 comments

Comments

@adg
Copy link
Contributor

adg commented Jun 26, 2011

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
Copy link
Contributor Author

adg commented Jun 26, 2011

@rsc
Copy link
Contributor

rsc commented Jun 27, 2011

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
Copy link
Contributor

rsc commented Dec 9, 2011

Comment 3:

Labels changed: added priority-later.

@rsc
Copy link
Contributor

rsc commented Dec 12, 2011

Comment 4:

Labels changed: added priority-go1.

@robpike
Copy link
Contributor

robpike commented Jan 13, 2012

Comment 5:

Owner changed to builder@golang.org.

@rsc
Copy link
Contributor

rsc commented Feb 28, 2012

Comment 7:

This issue was closed by revision 6e2ae0a.

Status changed to Fixed.

@rsc rsc added this to the Go1 milestone Apr 10, 2015
@rsc rsc removed the priority-go1 label Apr 10, 2015
@golang golang locked and limited conversation to collaborators Jun 24, 2016
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

4 participants