runtime/pprof: spurious prints during profiling on arm (about 1 in 15 minutes)

[bradfitz]

From Ignacio Grande on golang-nuts,

On Go 1.3rc1, ARM + profiling yields:

unexpected return pc for fmt.(*ss).doScanf called from 0x1

"To reproduce the steps I simply compile it and execute it with no arguments. In a
few seconds you should see some of those unexpected errors on screen, mixed with the
Count messages."

Repro code & data: https://db.tt/ogMKqKi5

I confirmed this behavior with Go tip (b476a7d) on a Chromebook with a Debian chroot.

Code, for easier linking is: http://play.golang.org/p/JSdMUdGIrW

No unsafe, no races (no goroutines).

[bradfitz]

Comment 2:

I've minimized this further, and it no longer requires a 23 MB data file or third-party
deps.
Code: http://play.golang.org/p/yOHdaBeFCQ
Output: http://play.golang.org/p/Ao0mgpPskJ

[siritinga]

Comment 3:

I've made a minimum version, 17 lines: http://play.golang.org/p/3SSAlZ1_En
Now I'm getting unexpected return pc also from runtime.mallocgc:
runtime: unexpected return pc for runtime.mallocgc called from 0x1032e040
runtime: unexpected return pc for fmt.(*ss).doScanf called from 0xb6e40ee4
runtime: unexpected return pc for fmt.(*ss).doScanf called from 0xb6e40ee4
runtime: unexpected return pc for runtime.mallocgc called from 0x1032e040
runtime: unexpected return pc for runtime.mallocgc called from 0x1032e040
runtime: unexpected return pc for runtime.mallocgc called from 0x1032e040
runtime: unexpected return pc for fmt.(*ss).doScanf called from 0xb6e40ee4
runtime: unexpected return pc for fmt.(*ss).doScanf called from 0xb6e40ee4

[rsc]

Comment 5:

This happens when the profiling signal arrives during runtime.jmpdefer. The traceback
ends up misreading memory and gets confused. It could just as easily have been crashing.
I will submit a CL for Go 1.3 that does not attempt to walk past jmpdefer. For Go 1.4 we
might want to look at making jmpdefer's modification of PC/SP/LR atomic so that it is
not possible to see an inconsistent triple.

Labels changed: added release-go1.4, removed release-go1.3maybe.

[gopherbot]

Comment 6:

CL https://golang.org/cl/107970043 mentions this issue.

[rsc]

Comment 7:

This issue was updated by revision 597f87c.

LGTM=minux, iant
R=golang-codereviews, minux, iant
CC=golang-codereviews, r
https://golang.org/cl/107970043

[gopherbot]

Comment 8:

CL https://golang.org/cl/101260043 mentions this issue.

[rsc]

Comment 9:

This issue was updated by revision 06752081de7d.
LGTM=minux, iant
R=golang-codereviews, minux, iant
CC=golang-codereviews, r
https://golang.org/cl/107970043
»»»
LGTM=r
R=golang-codereviews, r
CC=adg, golang-codereviews, iant
https://golang.org/cl/101260043

[gopherbot]

Comment 10:

CL https://golang.org/cl/109920044 mentions this issue.

[siritinga]

Comment 11:

After the last commit, the error rate has been greatly reduced (may be 50x less frequent
or so) but it is still present:
45 minutes in a Raspberry Pi:
$ ./test
runtime: unexpected return pc for fmt.Fscanf called from 0xb6f22000
runtime: unexpected return pc for fmt.(*ss).doScanf called from 0x1
runtime: unexpected return pc for fmt.(*ss).scanInt called from 0xb6e43d04

[rsc]

Comment 12:

Labels changed: added release-go1.3.1, removed release-go1.4.

[minux]

Comment 13:

I ran the example code in #3 for ~9 hours, and there is only one line:
runtime: unexpected return pc for runtime.sweepone called from 0xffffe2c0
(PS: I ran with my CL 109920044.)

[gopherbot]

Comment 14:

CL https://golang.org/cl/118670043 mentions this issue.

[rsc]

Comment 15:

Status changed to Started.

[rsc]

Comment 16:

This issue was closed by revision e5e547c.

Status changed to Fixed.

[rsc]

Comment 17:

Trivial fix for problem with no workaround.
Approved for Go 1.3.1.

[adg]

Comment 18:

This issue was closed by revision 1ebf7615d3a7.

[adg]

Comment 19:

Applied to release-branch.go1.3.