cmd/compile: "go test" taking ~38x longer on Go tip than on Go 1.4

[mewmew]

1. What version of Go are you using (go version)?

For Go tip

[~]$ go version
go version devel +0659cf6 Wed Mar 23 19:22:53 2016 +0000 linux/amd64

and for Go 1.4

[~]$ go version
go version go1.4.3 linux/amd64

1. What operating system and processor architecture are you using (go env)?

For Go tip

[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/tmp/gotip"
GORACE=""
GOROOT="/home/u/go"
GOTOOLDIR="/home/u/go/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build981577852=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"

and for Go 1.4

[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ go env
GOARCH="amd64"
GOBIN=""
GOCHAR="6"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/tmp/go14"
GORACE=""
GOROOT="/home/u/go1.4"
GOTOOLDIR="/home/u/go1.4/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"

1. What did you do?
   If possible, provide a recipe for reproducing the error.
   A complete runnable program is good.
   A link on play.golang.org is best.

For Go tip

[~]$ export GOPATH=/tmp/gotip
[~]$ go get github.com/mewmew/uc
[~]$ go get github.com/goccmack/gocc
[~]$ export PATH=${GOPATH}/bin:${PATH}
[~]$ cd ${GOPATH}/src/github.com/mewmew/uc
[/tmp/gotip/src/github.com/mewmew/uc]$ git checkout 9557c0010cde8953d0719ab5df170b8cfbdc3a3f
[/tmp/gotip/src/github.com/mewmew/uc]$ cd uc/gocc
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc]$ make gen
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc]$ cd lexer
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 21:05:38 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 21:05:38 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 21:05:38 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 21:05:38 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 21:05:38 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 21:05:38 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 21:05:38 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 21:05:38 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 21:05:38 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 21:05:38 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m20.810s
user    0m33.817s
sys 0m0.977s
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go install

real    0m0.120s
user    0m0.113s
sys 0m0.023s
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 21:06:18 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 21:06:18 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 21:06:18 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 21:06:18 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 21:06:18 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 21:06:18 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 21:06:18 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 21:06:18 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 21:06:18 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 21:06:18 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.001s

real    0m20.752s
user    0m34.110s
sys 0m0.953s
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test -i

real    0m0.057s
user    0m0.030s
sys 0m0.020s
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 21:07:15 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 21:07:15 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 21:07:15 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 21:07:15 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 21:07:15 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 21:07:15 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 21:07:15 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 21:07:15 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 21:07:15 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 21:07:15 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m20.751s
user    0m33.750s
sys 0m1.007s

and for Go 1.4

[~]$ export GOPATH=/tmp/go14
[~]$ go get github.com/mewmew/uc
[~]$ go get github.com/goccmack/gocc
[~]$ export PATH=${GOPATH}/bin:${PATH}
[~]$ cd ${GOPATH}/src/github.com/mewmew/uc
[/tmp/go14/src/github.com/mewmew/uc]$ git checkout 9557c0010cde8953d0719ab5df170b8cfbdc3a3f
[/tmp/go14/src/github.com/mewmew/uc]$ cd uc/gocc
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc]$ make gen
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc]$ cd lexer
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 21:05:42 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 21:05:42 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 21:05:42 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 21:05:42 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 21:05:42 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 21:05:42 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 21:05:42 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 21:05:42 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 21:05:42 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 21:05:42 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m0.588s
user    0m0.503s
sys 0m0.053s
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go install

real    0m0.053s
user    0m0.040s
sys 0m0.007s
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 21:06:43 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 21:06:43 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 21:06:43 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 21:06:43 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 21:06:43 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 21:06:43 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 21:06:43 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 21:06:43 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 21:06:43 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 21:06:43 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m0.547s
user    0m0.483s
sys 0m0.057s
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test -i

real    0m0.034s
user    0m0.033s
sys 0m0.000s
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 21:06:52 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 21:06:52 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 21:06:52 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 21:06:52 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 21:06:52 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 21:06:52 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 21:06:52 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 21:06:52 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 21:06:52 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 21:06:52 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m0.545s
user    0m0.503s
sys 0m0.037s

1. What did you expect to see?

The time take by go test github.com/mewmew/uc/uc/gocc/lexer taking roughly the same amount of time to run when using Go tip and Go 1.4.

1. What did you see instead?

"go test" took roughly 20 seconds on Go tip and 0.5 seconds on Go 1.4.

Also note that the compile command used between 25% to 60% of the CPU, during the 20 second duration.

[bradfitz]

Nuke your $GOPATH/pkg cache before both tests.

I suspect in one case you're building dependencies and in the other case you're not.

[mewmew]

I tried to remove the $GOPATH/pkg directory but did not make a difference.

For Go tip (21 sec)

[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ go version
go version devel +0659cf6 Wed Mar 23 19:22:53 2016 +0000 linux/amd64
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ ls ${GOPATH}
bin/  src/  ./  ../
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 22:45:30 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 22:45:30 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 22:45:30 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 22:45:30 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 22:45:30 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 22:45:30 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 22:45:30 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 22:45:30 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 22:45:30 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 22:45:30 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m21.939s
user    0m32.177s
sys 0m1.307s
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ ls ${GOPATH}
bin/  src/  ./  ../
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test -i

real    0m0.130s
user    0m0.133s
sys 0m0.007s
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ ls ${GOPATH}
bin/  pkg/  src/  ./  ../
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 22:46:22 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 22:46:22 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 22:46:22 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 22:46:22 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 22:46:22 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 22:46:22 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 22:46:22 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 22:46:22 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 22:46:22 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 22:46:22 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m21.440s
user    0m33.103s
sys 0m0.783s

For Go 1.4 (0.6 sec)

[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ go version
go version go1.4.3 linux/amd64
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ ls ${GOPATH}
bin/  src/  ./  ../
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 22:45:06 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 22:45:06 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 22:45:06 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 22:45:06 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 22:45:06 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 22:45:06 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 22:45:06 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 22:45:06 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 22:45:06 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 22:45:06 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m0.595s
user    0m0.517s
sys 0m0.067s
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ ls ${GOPATH}
bin/  src/  ./  ../
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test -i

real    0m0.065s
user    0m0.047s
sys 0m0.013s
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ ls ${GOPATH}
bin/  pkg/  src/  ./  ../
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test
2016/03/23 22:46:24 path: ../../testdata/incorrect/lexer/bad.c
2016/03/23 22:46:24 path: ../../testdata/incorrect/lexer/good.c
2016/03/23 22:46:24 path: ../../testdata/incorrect/lexer/long-char.c
2016/03/23 22:46:24 path: ../../testdata/incorrect/lexer/ugly.c
2016/03/23 22:46:24 path: ../../testdata/quiet/lexer/l01.c
2016/03/23 22:46:24 path: ../../testdata/quiet/lexer/l02.c
2016/03/23 22:46:24 path: ../../testdata/quiet/lexer/l03.c
2016/03/23 22:46:24 path: ../../testdata/quiet/lexer/l04.c
2016/03/23 22:46:24 path: ../../testdata/quiet/lexer/l05.c
2016/03/23 22:46:24 path: ../../testdata/quiet/lexer/l06.c
PASS
ok      github.com/mewmew/uc/uc/gocc/lexer  0.002s

real    0m0.567s
user    0m0.520s
sys 0m0.040s

[mdempsky]

Try running go test -x -c with both 1.4 and tip. Are there any differences in build actions?

[bradfitz]

The SSA compiler is very slow with the large, auto-generated lexer_test.go.

CPU and memory profiles follow:

(pprof) top --cum 20
6.61s of 38.69s total (17.08%)
Dropped 294 nodes (cum <= 0.19s)
Showing top 20 nodes out of 85 (cum >= 7.55s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     37.39s 96.64%  runtime.goexit
         0     0%     0%     25.62s 66.22%  cmd/compile/internal/amd64.Main
         0     0%     0%     25.62s 66.22%  cmd/compile/internal/gc.Main
         0     0%     0%     25.62s 66.22%  main.main
         0     0%     0%     25.62s 66.22%  runtime.main
         0     0%     0%     25.51s 65.93%  cmd/compile/internal/gc.funccompile
         0     0%     0%     25.46s 65.81%  cmd/compile/internal/gc.compile
         0     0%     0%     25.23s 65.21%  cmd/compile/internal/gc.buildssa
         0     0%     0%     16.41s 42.41%  cmd/compile/internal/ssa.Compile
     6.06s 15.66% 15.66%     12.98s 33.55%  runtime.scanobject
         0     0% 15.66%     11.69s 30.21%  runtime.gcBgMarkWorker
     0.19s  0.49% 16.15%     11.66s 30.14%  runtime.gcDrain
     0.17s  0.44% 16.59%     11.16s 28.84%  runtime.mallocgc
     0.04s   0.1% 16.70%     10.99s 28.41%  runtime.systemstack
     0.02s 0.052% 16.75%      8.76s 22.64%  cmd/compile/internal/gc.(*state).linkForwardReferences
     0.04s   0.1% 16.85%      8.74s 22.59%  cmd/compile/internal/gc.(*state).resolveFwdRef
     0.09s  0.23% 17.08%      8.60s 22.23%  cmd/compile/internal/gc.(*state).lookupVarOutgoing
         0     0% 17.08%      8.29s 21.43%  cmd/compile/internal/ssa.regalloc
         0     0% 17.08%      7.55s 19.51%  runtime.(*mcache).refill
         0     0% 17.08%      7.55s 19.51%  runtime.(*mcentral).cacheSpan

(pprof) top 20
33550ms of 38690ms total (86.71%)
Dropped 294 nodes (cum <= 193.45ms)
Showing top 20 nodes out of 85 (cum >= 240ms)
      flat  flat%   sum%        cum   cum%
    6260ms 16.18% 16.18%     7490ms 19.36%  runtime.(*mcentral).grow
    6060ms 15.66% 31.84%    12980ms 33.55%  runtime.scanobject
    4180ms 10.80% 42.65%     4180ms 10.80%  cmd/compile/internal/ssa.copyelimValue
    3740ms  9.67% 52.31%     3740ms  9.67%  runtime.heapBitsForObject
    2740ms  7.08% 59.40%     3210ms  8.30%  runtime.greyobject
    2690ms  6.95% 66.35%     2690ms  6.95%  runtime.memclr
    1270ms  3.28% 69.63%     3410ms  8.81%  cmd/compile/internal/ssa.deadcode
    1070ms  2.77% 72.40%     1070ms  2.77%  runtime.duffcopy
     880ms  2.27% 74.67%      880ms  2.27%  runtime.memmove
     680ms  1.76% 76.43%      750ms  1.94%  runtime.evacuate
     660ms  1.71% 78.13%      890ms  2.30%  cmd/compile/internal/ssa.(*regAllocState).computeLive
     550ms  1.42% 79.56%      550ms  1.42%  cmd/compile/internal/ssa.(*Value).resetArgs
     510ms  1.32% 80.87%      700ms  1.81%  cmd/compile/internal/ssa.(*sparseSet).addAll
     470ms  1.21% 82.09%      470ms  1.21%  runtime.usleep
     390ms  1.01% 83.10%      490ms  1.27%  runtime.(*mheap).allocSpanLocked
     380ms  0.98% 84.08%     2340ms  6.05%  runtime.mapassign1
     290ms  0.75% 84.83%     2800ms  7.24%  cmd/compile/internal/ssa.(*edgeState).setup
     290ms  0.75% 85.58%      290ms  0.75%  runtime/internal/atomic.Or8
     230ms  0.59% 86.17%      250ms  0.65%  cmd/compile/internal/ssa.phielimValue
     210ms  0.54% 86.71%      240ms  0.62%  runtime.mapaccess2_fast64


(pprof) top --cum 30
4602.42MB of 5030.21MB total (91.50%)
Dropped 233 nodes (cum <= 25.15MB)
Showing top 30 nodes out of 37 (cum >= 96.28MB)
      flat  flat%   sum%        cum   cum%
         0     0%     0%  5026.71MB 99.93%  cmd/compile/internal/gc.Main
         0     0%     0%  5025.71MB 99.91%  cmd/compile/internal/amd64.Main
         0     0%     0%  5025.21MB 99.90%  main.main
         0     0%     0%  5024.21MB 99.88%  runtime.main
         0     0%     0%  5023.21MB 99.86%  runtime.goexit
         0     0%     0%  4999.15MB 99.38%  cmd/compile/internal/gc.funccompile
         0     0%     0%  4997.98MB 99.36%  cmd/compile/internal/gc.compile
         0     0%     0%  4955.84MB 98.52%  cmd/compile/internal/gc.buildssa
         0     0%     0%  3249.92MB 64.61%  cmd/compile/internal/ssa.Compile
         0     0%     0%  2293.67MB 45.60%  cmd/compile/internal/ssa.regalloc
  173.93MB  3.46%  3.46%  1697.45MB 33.75%  cmd/compile/internal/ssa.(*regAllocState).regalloc
         0     0%  3.46%  1682.08MB 33.44%  cmd/compile/internal/gc.(*state).linkForwardReferences
         0     0%  3.46%  1682.08MB 33.44%  cmd/compile/internal/gc.(*state).resolveFwdRef
  579.61MB 11.52% 14.98%  1663.08MB 33.06%  cmd/compile/internal/gc.(*state).lookupVarOutgoing
  967.46MB 19.23% 34.21%   967.46MB 19.23%  cmd/compile/internal/ssa.(*Func).newValue
         0     0% 34.21%   961.44MB 19.11%  cmd/compile/internal/ssa.(*Block).NewValue0A
         0     0% 34.21%   853.75MB 16.97%  cmd/compile/internal/ssa.stackalloc
  630.77MB 12.54% 46.75%   630.77MB 12.54%  cmd/compile/internal/ssa.(*Func).setHome
         0     0% 46.75%   630.77MB 12.54%  cmd/compile/internal/ssa.(*regAllocState).assignReg
  350.85MB  6.97% 53.73%   596.22MB 11.85%  cmd/compile/internal/ssa.(*regAllocState).init
  233.10MB  4.63% 58.36%   495.48MB  9.85%  cmd/compile/internal/ssa.(*stackAllocState).init
  356.95MB  7.10% 65.46%   358.26MB  7.12%  cmd/compile/internal/ssa.(*stackAllocState).stackalloc
  292.95MB  5.82% 71.28%   295.07MB  5.87%  cmd/compile/internal/ssa.cse
  272.54MB  5.42% 76.70%   272.54MB  5.42%  cmd/compile/internal/ssa.schedule
  244.27MB  4.86% 81.56%   245.37MB  4.88%  cmd/compile/internal/ssa.(*regAllocState).computeLive
  201.41MB  4.00% 85.56%   201.41MB  4.00%  cmd/compile/internal/ssa.(*stackAllocState).buildInterferenceGraph
  174.84MB  3.48% 89.04%   174.84MB  3.48%  cmd/compile/internal/ssa.(*Func).newSparseSet
  123.73MB  2.46% 91.50%   123.73MB  2.46%  cmd/compile/internal/gc.(*state).addNamedValue
         0     0% 91.50%   116.56MB  2.32%  cmd/compile/internal/ssa.dse
         0     0% 91.50%    96.28MB  1.91%  cmd/compile/internal/ssa.deadcode

(pprof) top 30
4.78GB of 4.91GB total (97.25%)
Dropped 233 nodes (cum <= 0.02GB)
Showing top 30 nodes out of 37 (cum >= 3.17GB)
      flat  flat%   sum%        cum   cum%
    0.94GB 19.23% 19.23%     0.94GB 19.23%  cmd/compile/internal/ssa.(*Func).newValue
    0.62GB 12.54% 31.77%     0.62GB 12.54%  cmd/compile/internal/ssa.(*Func).setHome
    0.57GB 11.52% 43.30%     1.62GB 33.06%  cmd/compile/internal/gc.(*state).lookupVarOutgoing
    0.35GB  7.10% 50.39%     0.35GB  7.12%  cmd/compile/internal/ssa.(*stackAllocState).stackalloc
    0.34GB  6.97% 57.37%     0.58GB 11.85%  cmd/compile/internal/ssa.(*regAllocState).init
    0.29GB  5.82% 63.19%     0.29GB  5.87%  cmd/compile/internal/ssa.cse
    0.27GB  5.42% 68.61%     0.27GB  5.42%  cmd/compile/internal/ssa.schedule
    0.24GB  4.86% 73.46%     0.24GB  4.88%  cmd/compile/internal/ssa.(*regAllocState).computeLive
    0.23GB  4.63% 78.10%     0.48GB  9.85%  cmd/compile/internal/ssa.(*stackAllocState).init
    0.20GB  4.00% 82.10%     0.20GB  4.00%  cmd/compile/internal/ssa.(*stackAllocState).buildInterferenceGraph
    0.17GB  3.48% 85.58%     0.17GB  3.48%  cmd/compile/internal/ssa.(*Func).newSparseSet
    0.17GB  3.46% 89.04%     1.66GB 33.75%  cmd/compile/internal/ssa.(*regAllocState).regalloc
    0.12GB  2.46% 91.50%     0.12GB  2.46%  cmd/compile/internal/gc.(*state).addNamedValue
    0.09GB  1.88% 93.38%     0.09GB  1.88%  cmd/compile/internal/ssa.tighten
    0.06GB  1.18% 94.56%     0.06GB  1.21%  cmd/compile/internal/ssa.(*stackAllocState).computeLive
    0.06GB  1.17% 95.73%     0.06GB  1.17%  cmd/compile/internal/ssa.critical
    0.04GB  0.78% 96.50%     0.04GB  0.78%  cmd/compile/internal/ssa.(*edgeState).set
    0.04GB  0.75% 97.25%     0.04GB  0.75%  cmd/compile/internal/ssa.liveValues
         0     0% 97.25%     4.91GB 99.91%  cmd/compile/internal/amd64.Main
         0     0% 97.25%     1.64GB 33.44%  cmd/compile/internal/gc.(*state).linkForwardReferences
         0     0% 97.25%     1.64GB 33.44%  cmd/compile/internal/gc.(*state).resolveFwdRef
         0     0% 97.25%     4.91GB 99.93%  cmd/compile/internal/gc.Main
         0     0% 97.25%     4.84GB 98.52%  cmd/compile/internal/gc.buildssa
         0     0% 97.25%     4.88GB 99.36%  cmd/compile/internal/gc.compile
         0     0% 97.25%     4.88GB 99.38%  cmd/compile/internal/gc.funccompile
         0     0% 97.25%     0.94GB 19.11%  cmd/compile/internal/ssa.(*Block).NewValue0A
         0     0% 97.25%     0.04GB  0.78%  cmd/compile/internal/ssa.(*edgeState).setup
         0     0% 97.25%     0.62GB 12.54%  cmd/compile/internal/ssa.(*regAllocState).assignReg
         0     0% 97.25%     0.04GB  0.78%  cmd/compile/internal/ssa.(*regAllocState).shuffle
         0     0% 97.25%     3.17GB 64.61%  cmd/compile/internal/ssa.Compile

[minux]

The old compiler has a cutoff threshold: when a function uses more than some certain number of instructions, it will skip the optimization step. Perhaps we could preserve the old backend for such cases. (That is, if the input function is too complicated, just fallback to the old backend.)

[griesemer]

I would certainly hope that we can remove the old backend eventually. It
seems like a bad idea to have to maintain two different backends in one
compiler forever.

• gri

On Wed, Mar 23, 2016 at 4:02 PM, Minux Ma notifications@github.com wrote:

The old compiler has a cutoff threshold: when a function uses more than
some certain number of instructions, it will skip the optimization step.
Perhaps we could preserve the old backend for such cases.

(That is, if the input function is too complicated, just fallback to the
old backend.)

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#14934 (comment)

[mewmew]

Try running go test -x -c with both 1.4 and tip. Are there any differences in build actions?

On Go tip

[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ go version
go version devel +0659cf6 Wed Mar 23 19:22:53 2016 +0000 linux/amd64
[/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test -x -c
WORK=/tmp/go-build249655493
mkdir -p $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/
mkdir -p $WORK/github.com/mewmew/uc/uc/gocc/token/_obj/
mkdir -p $WORK/github.com/mewmew/uc/uc/gocc/
cd /home/u/Desktop/go/src/github.com/mewmew/uc/uc/gocc/token
/home/u/go/pkg/tool/linux_amd64/compile -o $WORK/github.com/mewmew/uc/uc/gocc/token.a -trimpath $WORK -p github.com/mewmew/uc/uc/gocc/token -complete -buildid 8b7f374d1fc5ffa423d5d240641f029151c72b20 -D _/home/u/Desktop/go/src/github.com/mewmew/uc/uc/gocc/token -I $WORK -pack ./token.go
mkdir -p $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_obj/
mkdir -p $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/
cd /tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer
/home/u/go/pkg/tool/linux_amd64/compile -o $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer.a -trimpath $WORK -p _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer -complete -buildid 217e99cb067119187679a189a2297c23179ff229 -D _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./acttab.go ./lexer.go ./transitiontable.go
mkdir -p $WORK/github.com/mewmew/uc/uc/gocc/lexer/_obj/
cd /home/u/Desktop/go/src/github.com/mewmew/uc/uc/gocc/lexer
/home/u/go/pkg/tool/linux_amd64/compile -o $WORK/github.com/mewmew/uc/uc/gocc/lexer.a -trimpath $WORK -p github.com/mewmew/uc/uc/gocc/lexer -complete -buildid 217e99cb067119187679a189a2297c23179ff229 -D _/home/u/Desktop/go/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./acttab.go ./lexer.go ./transitiontable.go
mkdir -p $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_obj_xtest/
cd /tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer
/home/u/go/pkg/tool/linux_amd64/compile -o $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer_test.a -trimpath $WORK -p _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer_test -complete -D _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./lexer_test.go
mkdir -p $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/
cd $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test
/home/u/go/pkg/tool/linux_amd64/compile -o ./main.a -trimpath $WORK -p main -complete -D "" -I . -I $WORK -pack ./_testmain.go
cd .
/home/u/go/pkg/tool/linux_amd64/link -o $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/lexer.test -L $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test -L $WORK -L /home/u/Desktop/go/pkg/linux_amd64 -extld=gcc -buildmode=exe $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/main.a
mkdir -p /tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/
mv $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/lexer.test /tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/lexer.test

real    0m22.553s
user    0m35.083s
sys 0m1.483s

On Go 1.4

[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ go version
go version go1.4.3 linux/amd64
[/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer]$ time go test -x -c
WORK=/tmp/go-build431641544
mkdir -p $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/
mkdir -p $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_obj/
mkdir -p $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/
cd /tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer
/home/u/go1.4/pkg/tool/linux_amd64/6g -o $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer.a -trimpath $WORK -p _/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer -complete -D _/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./acttab.go ./lexer.go ./transitiontable.go
mkdir -p $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_obj_xtest/
/home/u/go1.4/pkg/tool/linux_amd64/6g -o $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer_test.a -trimpath $WORK -p _/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer_test -complete -D _/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./lexer_test.go
mkdir -p $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/
cd $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test
/home/u/go1.4/pkg/tool/linux_amd64/6g -o ./main.a -trimpath $WORK -p testmain -complete -D "" -I . -I $WORK -pack ./_testmain.go
cd .
/home/u/go1.4/pkg/tool/linux_amd64/6l -o $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/lexer.test -L $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test -L $WORK -L /home/u/Desktop/go/pkg/linux_amd64 -extld=gcc $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/main.a
mkdir -p /tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/
mv $WORK/_/tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/_test/lexer.test /tmp/go14/src/github.com/mewmew/uc/uc/gocc/lexer/lexer.test

real    0m0.599s
user    0m0.557s
sys 0m0.050s

[mewmew]

@mdempsky The step which takes most of the time for Go tip is the following:

/home/u/go/pkg/tool/linux_amd64/compile -o $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/_test/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer_test.a -trimpath $WORK -p _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer_test -complete -D _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./lexer_test.go

[davecheney]

Can you please provide a link to that source. I cannot figure out which
branch of your repo I need to compile.

On Thu, Mar 24, 2016 at 10:28 AM, Robin Eklind notifications@github.com
wrote:

@mdempsky https://github.com/mdempsky The step which takes most of the
time for Go tip is the following:

/home/u/go/pkg/tool/linux_amd64/compile -o $WORK/_/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer/test//tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer_test.a -trimpath $WORK -p _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer_test -complete -D _/tmp/gotip/src/github.com/mewmew/uc/uc/gocc/lexer -I $WORK -I /home/u/Desktop/go/pkg/linux_amd64 -pack ./lexer_test.go

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub
#14934 (comment)

[cespare]

@davecheney https://github.com/mewmew/uc/blob/9557c0010cde8953d0719ab5df170b8cfbdc3a3f/uc/gocc/lexer/lexer_test.go

(The sha is given in the report.)

[davecheney]

I am sorry, this revision does not compile cleanly for me

github.com/mewmew/uc/uc/gocc/lexer

lexer_test.go:11:2: cannot find package "github.com/mewmew/uc/uc/gocc/token"
in any of:
/home/dfc/go/src/github.com/mewmew/uc/uc/gocc/token (from $GOROOT)
/home/dfc/src/github.com/mewmew/uc/uc/gocc/token (from $GOPATH)

% ls $GOPATH/src/github.com/mewmew/uc/uc/gocc/
lexer Makefile uc.bnf

On Thu, Mar 24, 2016 at 10:52 AM, Caleb Spare notifications@github.com
wrote:

@davecheney https://github.com/davecheney
https://github.com/mewmew/uc/blob/9557c0010cde8953d0719ab5df170b8cfbdc3a3f/uc/gocc/lexer/lexer_test.go

(The sha is given in the report.)

—
You are receiving this because you were mentioned.
Reply to this email directly or view it on GitHub
#14934 (comment)

[bradfitz]

@davecheney, I was able to follow the instructions to repro to get my numbers above.