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: spurious prints during profiling on arm (about 1 in 15 minutes) #8153

Closed
bradfitz opened this issue Jun 4, 2014 · 17 comments
Closed

Comments

@bradfitz
Copy link
Contributor

bradfitz commented Jun 4, 2014

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

bradfitz commented Jun 4, 2014

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

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

rsc commented Jun 12, 2014

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

Comment 6:

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

@rsc
Copy link
Contributor

rsc commented Jun 12, 2014

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

Comment 8:

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

@rsc
Copy link
Contributor

rsc commented Jun 12, 2014

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

Comment 10:

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

@siritinga
Copy link

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

rsc commented Jun 13, 2014

Comment 12:

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

@minux
Copy link
Member

minux commented Jun 13, 2014

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

Comment 14:

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

@rsc
Copy link
Contributor

rsc commented Aug 6, 2014

Comment 15:

Status changed to Started.

@rsc
Copy link
Contributor

rsc commented Aug 6, 2014

Comment 16:

This issue was closed by revision e5e547c.

Status changed to Fixed.

@rsc
Copy link
Contributor

rsc commented Aug 11, 2014

Comment 17:

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

@adg
Copy link
Contributor

adg commented Aug 11, 2014

Comment 18:

This issue was closed by revision 1ebf7615d3a7.

@adg
Copy link
Contributor

adg commented Aug 11, 2014

Comment 19:

Applied to release-branch.go1.3.

@rsc rsc added this to the Go1.3.1 milestone Apr 14, 2015
rsc added a commit that referenced this issue May 11, 2015
…of traceback on arm

««« CL 107970043 / b336da131a84
runtime: do not trace past jmpdefer during pprof traceback on arm

jmpdefer modifies PC, SP, and LR, and not atomically,
so walking past jmpdefer will often end up in a state
where the three are not a consistent execution snapshot.
This was causing warning messages a few frames later
when the traceback realized it was confused, but given
the right memory it could easily crash instead.

Update #8153

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
adg added a commit that referenced this issue May 11, 2015
… on arm traceback

««« CL 118670043 / 671fa8a9eb80
runtime: turn off 'unexpected return pc' print on arm traceback

It can happen legitimately if a profiling signal arrives at just the wrong moment.
It's harmless.

Fixes #8153.

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

TBR=rsc
CC=golang-codereviews
https://golang.org/cl/127950044
@golang golang locked and limited conversation to collaborators Jun 25, 2016
wheatman pushed a commit to wheatman/go-akaros that referenced this issue Jun 25, 2018
It can happen legitimately if a profiling signal arrives at just the wrong moment.
It's harmless.

Fixes golang#8153.

LGTM=minux
R=golang-codereviews, minux
CC=golang-codereviews, iant, r
https://golang.org/cl/118670043
wheatman pushed a commit to wheatman/go-akaros that referenced this issue Jul 9, 2018
It can happen legitimately if a profiling signal arrives at just the wrong moment.
It's harmless.

Fixes golang#8153.

LGTM=minux
R=golang-codereviews, minux
CC=golang-codereviews, iant, r
https://golang.org/cl/118670043
@rsc rsc removed their assignment Jun 23, 2022
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

6 participants