Skip to content

runtime/pprof: hangs when using pprof on a CPU-intensive program on OS X #5519

@gopherbot

Description

@gopherbot

by akalin:

What steps will reproduce the problem?
If possible, include a link to a program on play.golang.org.
1. Download aks_debug.go from http://play.golang.org/p/SUNgPMcfIM or
https://github.com/akalin/aks-go/blob/debug/aks_debug.go
2. build (tested with go 1.1):

go build aks_debug.go

3. the most reliable way to repro would be to run:

for i in $(seq 1 300); do (env GOGCTRACE=1 ./aks_debug >&/tmp/aks_debug.$i
&); done

You'd expect all programs to terminate, but chances are, when your computer settles
down, there will be one or two
aks_debug processes still hanging around. Check with ps. For example:

  PID TTY           TIME CMD
23780 ttys000    0:00.01 -bash
23826 ttys000    0:00.00 tmux att
26765 ttys001    0:02.11 -bash
27792 ttys001    0:02.04 ./aks_debug
27904 ttys001    0:02.09 ./aks_debug
17273 ttys002    0:00.04 -bash
 6770 ttys003    0:00.83 -bash

Check which output files correspond to those processes:
$ lsof /tmp/aks_debug.*
COMMAND     PID   USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
aks_debug 27792 akalin    1w   REG    1,4     2404 9553026
/private/tmp/aks_debug.5
aks_debug 27792 akalin    2w   REG    1,4     2404 9553026
/private/tmp/aks_debug.5
aks_debug 27904 akalin    1w   REG    1,4     2404 9553082
/private/tmp/aks_debug.61
aks_debug 27904 akalin    2w   REG    1,4     2404 9553082
/private/tmp/aks_debug.61

Then send a SIGQUIT to one of those to get the output:

kill -s SIGQUIT 27792
less /tmp/aks_debug.5

For example, I get the below log output. Looks like it's stuck on a
write syscall for the pprof output?

Let me know if I can do anything more.

-- START aks_debug.5 --

gc1(1): 0+0+0 ms, 0 -> 0 MB 20 -> 22 (23-1) objects, 0(0) handoff, 0(0) steal, 0
/0/0 yields
2013/05/14 02:33:47 0: multiplying...
2013/05/14 02:33:47 0: multiplying done; shifting...
2013/05/14 02:33:47 0: not shifting
2013/05/14 02:33:47 1: multiplying...
2013/05/14 02:33:47 1: multiplying done; shifting...
2013/05/14 02:33:47 1: not shifting
2013/05/14 02:33:47 2: multiplying...
2013/05/14 02:33:47 2: multiplying done; shifting...
2013/05/14 02:33:47 2: not shifting
2013/05/14 02:33:47 3: multiplying...
2013/05/14 02:33:47 3: multiplying done; shifting...
2013/05/14 02:33:47 3: not shifting
2013/05/14 02:33:47 4: multiplying...
2013/05/14 02:33:47 4: multiplying done; shifting...
2013/05/14 02:33:47 4: not shifting
2013/05/14 02:33:47 5: multiplying...
2013/05/14 02:33:47 5: multiplying done; shifting...
2013/05/14 02:33:47 5: not shifting
2013/05/14 02:33:47 6: multiplying...
2013/05/14 02:33:47 6: multiplying done; shifting...
2013/05/14 02:33:47 6: not shifting
2013/05/14 02:33:47 7: multiplying...
2013/05/14 02:33:47 7: multiplying done; shifting...
2013/05/14 02:33:47 7: not shifting
2013/05/14 02:33:47 8: multiplying...
2013/05/14 02:33:47 8: multiplying done; shifting...
2013/05/14 02:33:47 8: not shifting
2013/05/14 02:33:47 9: multiplying...
gc2(1): 0+0+0 ms, 0 -> 0 MB 206 -> 144 (229-85) objects, 0(0) handoff, 0(0) stea
l, 0/0/0 yields
2013/05/14 02:33:47 9: multiplying done; shifting...
2013/05/14 02:33:47 9: not shifting
2013/05/14 02:33:47 10: multiplying...
2013/05/14 02:33:47 10: multiplying done; shifting...
2013/05/14 02:33:47 10: not shifting
2013/05/14 02:33:47 11: multiplying...
gc3(1): 0+0+0 ms, 1 -> 1 MB 154 -> 144 (240-96) objects, 0(0) handoff, 0(0) stea
l, 0/0/0 yields
2013/05/14 02:33:47 11: multiplying done; shifting...
2013/05/14 02:33:47 11: not shifting
2013/05/14 02:33:47 12: multiplying...
gc4(1): 0+0+0 ms, 2 -> 2 MB 150 -> 145 (247-102) objects, 0(0) handoff, 0(0) ste
al, 0/0/0 yields
2013/05/14 02:33:48 12: multiplying done; shifting...
2013/05/14 02:33:48 12: not shifting
2013/05/14 02:33:48 13: multiplying...
gc5(1): 0+0+0 ms, 4 -> 3 MB 150 -> 145 (253-108) objects, 0(0)
handoff, 0(0) steal, 0/0/0 yields
2013/05/14 02:34:00 13: multiplying done; shifting...
2013/05/14 02:34:00 13: not shifting
2013/05/14 02:34:00 14: multiplying...
gc6(1): 0+0+0 ms, 7 -> 6 MB 149 -> 144 (258-114) objects, 0(0) handoff, 0(0) ste
al, 0/0/0 yields
SIGQUIT: quit
PC=0x229fb

Which compiler are you using (5g, 6g, 8g, gccgo)?

Whatever go build on go 1.1 on x86 OS X uses.

Which operating system are you using?

OS X

Which version are you using?  (run 'go version')

go 1.1 (homebrew)

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions