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.

Sign up for GitHub

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

Jump to bottom

cmd/compile: extraneous line number info #16380

Closed
ghost opened this issue Jul 14, 2016 · 6 comments
Closed

cmd/compile: extraneous line number info #16380

ghost opened this issue Jul 14, 2016 · 6 comments
Labels
FrozenDueToAge
Milestone
Go1.8

Comments

@ghost
Copy link

ghost commented Jul 14, 2016

Please answer these questions before submitting your issue. Thanks!

  1. What version of Go are you using (go version)?
    go version go1.7rc1 windows/amd64
  2. What operating system and processor architecture are you using (go env)?
    windows/amd64
  3. What did you do?
    Profiling https://play.golang.org/p/pUyOao-V9w
  4. What did you expect to see?
    Assembly listing similar to pprof's 1.6.2 weblist:
runtime.(*mspan).sweep
c:/go/src/runtime/mgcsweep.go
  Total:        90ms      3.19s (flat, cum) 11.32%
    161            .          . // It clears the mark bits in preparation for the next GC round. 
    162            .          . // Returns true if the span was returned to heap. 
    163            .          . // If preserve=true, don't return it to heap nor relink in MCentral lists; 
    164            .          . // caller takes care of it. 
    165            .          . //TODO go:nowritebarrier 
    166            .          . func (s *mspan) sweep(preserve bool) bool { 
    167            .          .     // It's critical that we enter this function with preemption disabled, 
    168            .          .     // GC must not start while we are in the middle of this function. 
    169            .          .     _g_ := getg() 
    170            .          .     if _g_.m.locks == 0 && _g_.m.mallocing == 0 && _g_ != _g_.m.g0 { 
    171            .          .         throw("MSpan_Sweep: m is not locked") 
    172            .          .     } 
    173            .          .     sweepgen := mheap_.sweepgen 
    174            .          .     if s.state != mSpanInUse || s.sweepgen != sweepgen-1 { 
                   .          .   41e18f: MOVZX 0x3c(CX), BX                               c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e193: CMPL $0x0, BL                                    c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e196: JNE 0x41e967                                     c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e19c: MOVL 0x30(CX), BX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e19f: MOVL AX, BP                                      c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e1a1: DECL BP                                          c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e1a3: CMPL BP, BX                                      c:/go/src/runtime/mgcsweep.go:174
                   .          .   41e1a5: JNE 0x41e967                                     c:/go/src/runtime/mgcsweep.go:174

    175            .          .         print("MSpan_Sweep: state=", s.state, " sweepgen=", s.sweepgen, " mheap.sweepgen=", sweepgen, "\n") 
    176            .          .         throw("MSpan_Sweep: bad span state") 
    177            .          .     } 
    178            .          .  
    179            .          .     if trace.enabled { 
                   .          .   41e1ab: MOVZX 0x1a8d7e(IP), BX                           c:/go/src/runtime/mgcsweep.go:179
                   .          .   41e1b2: CMPL $0x0, BL                                    c:/go/src/runtime/mgcsweep.go:179
                   .          .   41e1b5: JE 0x41e1c4                                      c:/go/src/runtime/mgcsweep.go:179
                   .          .   41ea2e: JMP 0x41e1ab                                     c:/go/src/runtime/mgcsweep.go:179

    180            .          .         traceGCSweepStart() 
                   .          .   41e1b7: CALL runtime.traceGCSweepStart(SB)               c:/go/src/runtime/mgcsweep.go:180
                   .          .   41e1bc: MOVQ 0x168(SP), CX                               c:/go/src/runtime/mgcsweep.go:180

    181            .          .     }
  1. What did you see instead?
runtime.(*mspan).sweep
c:/go/src/runtime/mgcsweep.go
  Total:        20ms      170ms (flat, cum)  0.89%
    161            .          . // It clears the mark bits in preparation for the next GC round. 
    162            .          . // Returns true if the span was returned to heap. 
    163            .          . // If preserve=true, don't return it to heap nor relink in MCentral lists; 
    164            .          . // caller takes care of it. 
    165            .          . //TODO go:nowritebarrier 
    166            .          . func (s *mspan) sweep(preserve bool) bool { 
    167            .          .     // It's critical that we enter this function with preemption disabled, 
    168            .          .     // GC must not start while we are in the middle of this function. 
    169            .          .     _g_ := getg() 
    170            .          .     if _g_.m.locks == 0 && _g_.m.mallocing == 0 && _g_ != _g_.m.g0 { 
    171            .          .         throw("MSpan_Sweep: m is not locked") 
    172            .          .     } 
    173            .          .     sweepgen := mheap_.sweepgen 
    174            .          .     if s.state != mSpanInUse || s.sweepgen != sweepgen-1 { 
                   .          .   41d427: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d42f: MOVZX 0x64(DX), BX                               c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d433: MOVB BL, 0x29(SP)                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d437: TESTL BL, BL                                     c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d439: JNE 0x41de24                                     c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d43f: MOVL 0x58(DX), SI                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d442: LEAL -0x1(CX), DI                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d445: MOVL DI, 0x34(SP)                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d449: CMPL DI, SI                                      c:/go/src/runtime/mgcsweep.go:174
                   .          .   41d44b: JNE 0x41de24                                     c:/go/src/runtime/mgcsweep.go:174
                   .          .   41da11: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41da31: MOVQ 0xe0(SP), CX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41db4b: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41db5a: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41db84: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41dbcc: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41dc3d: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41dd62: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41ddac: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41de13: MOVQ 0xe0(SP), DX                                c:/go/src/runtime/mgcsweep.go:174
                   .          .   41de1b: MOVL 0x34(SP), DI                                c:/go/src/runtime/mgcsweep.go:174

    175            .          .         print("MSpan_Sweep: state=", s.state, " sweepgen=", s.sweepgen, " mheap.sweepgen=", sweepgen, "\n") 
    176            .          .         throw("MSpan_Sweep: bad span state") 
    177            .          .     } 
    178            .          .  
    179            .          .     if trace.enabled { 
                   .          .   41d451: MOVZX 0x124358(IP), BX                           c:/go/src/runtime/mgcsweep.go:179
                   .          .   41d458: TESTL BL, BL                                     c:/go/src/runtime/mgcsweep.go:179
                   .          .   41d45a: JNE 0x41de02                                     c:/go/src/runtime/mgcsweep.go:179

    180            .          .         traceGCSweepStart() 
                   .          .   41de02: CALL runtime.traceGCSweepStart(SB)               c:/go/src/runtime/mgcsweep.go:180

    181            .          .     }

Assembly listing from 41da11 to 41de1b is unnecessary.
version devel +4054769 produces same listing
@ianlancetaylor ianlancetaylor changed the title cmd/pprof: wrong assembly listing cmd/compile: extraneous line number info Jul 15, 2016
@ianlancetaylor
Copy link
Member

Based on the output of go tool objdump, this is a problem in the line number information generated by the compiler. I copied your test case into foo.go, and did

go build foo.go
go tool objdump foo | grep mgcsweep.go:174

The output was

mgcsweep.go:174 0x41c319    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41c321    0fb65a64            MOVZX 0x64(DX), BX
mgcsweep.go:174 0x41c325    885c2429            MOVL BL, 0x29(SP)
mgcsweep.go:174 0x41c329    84db                TESTL BL, BL
mgcsweep.go:174 0x41c32b    0f85e5090000            JNE 0x41cd16
mgcsweep.go:174 0x41c331    8b7258              MOVL 0x58(DX), SI
mgcsweep.go:174 0x41c334    8d79ff              LEAL -0x1(CX), DI
mgcsweep.go:174 0x41c337    897c2434            MOVL DI, 0x34(SP)
mgcsweep.go:174 0x41c33b    39fe                CMPL DI, SI
mgcsweep.go:174 0x41c33d    0f85d3090000            JNE 0x41cd16
mgcsweep.go:174 0x41c903    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41c923    488b8c24e0000000        MOVQ 0xe0(SP), CX
mgcsweep.go:174 0x41ca3d    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41ca4c    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41ca76    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41cabe    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41cb2f    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41cc54    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41cc9e    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41cd05    488b9424e0000000        MOVQ 0xe0(SP), DX
mgcsweep.go:174 0x41cd0d    8b7c2434            MOVL 0x34(SP), DI

As you can see, there are many loads from the stack that are attributed to mgcsweep.go:174, although the instruction addresses show that these are occurring in different parts of the code.

CC @randall77 @josharian @cherrymui

@ianlancetaylor ianlancetaylor added this to the Go1.7Maybe milestone Jul 15, 2016
@ianlancetaylor
Copy link
Member

While I don't know the cause, I want to comment that GCC has the notion of an IR instruction with no location. When debug info for such an instruction is generated, it simply inherits the location of the preceding instruction. Perhaps that would be appropriate here.

@cherrymui
Copy link
Member

It seems these loads come from "shuffle" step of the reg allocator, where it puts values to desired locations to satisfy merge edges. In this case, the load instruction is labelled with the line number of the spill (unlike the general case where it is labelled with the line number of the use). Maybe we should assign the line number based on its use as well?

However, the use information seems not carried to this step. I will see how simple to add it.

@adg adg modified the milestones: Go1.8, Go1.7Maybe Jul 18, 2016
@cherrymui
Copy link
Member

CL https://golang.org/cl/25082 is a tentative fix. Do the line numbers get better with this CL?

@gopherbot
Copy link
Contributor

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

gopherbot pushed a commit that referenced this issue Sep 16, 2016
@cherrymui
cmd/compile: label LoadReg with line number of the use
46ba590 
A tentative fix of #16380. It adds "line" everywhere...

This also reduces binary size slightly (cmd/go on ARM as an example):

			before		after
total binary size	8068097		8018945 (-0.6%)
.gopclntab		1195341		1179929 (-1.3%)
.debug_line		 689692		 652017 (-5.5%)

Change-Id: Ibda657c6999783c5bac180cbbba487006dbf0ed7
Reviewed-on: https://go-review.googlesource.com/25082
Reviewed-by: David Chase <drchase@google.com>
Run-TryBot: Cherry Zhang <cherryyz@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@cherrymui
Copy link
Member

Fixed in that CL.

@golang golang locked and limited conversation to collaborators Sep 16, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.8
Development

No branches or pull requests
4 participants
@ianlancetaylor @adg @gopherbot @cherrymui