Puzzled by a profiling result around allocations
611 views
Skip to first unread message
Harry B
Mar 20, 2017, 7:51:50 PM3/20/17
to golang-nuts
Hi,
As part of preparing an internal go talk to explain using strings vs bytes of the bufio.Scanner, I created two small samples https://play.golang.org/p/-TYycdHaPC and https://play.golang.org/p/L7W-jiaHdL , the only difference in the hot path is reducing the conversions from `[]byte` to `string` (later also avoids fmt module’s string conversions). Input being a 10 million line file. Match is only one line.
For the moment, ignore the fact that I am not checking for number of arguments, is doing unnecessary optimizations etc. I am trying to take a simple case to explain.
First version runs in 3 seconds, second in 2 seconds. For the slower version using `.Text()` 90+ percent of the time was in `syscall.Syscall` (under syscall.Read on the file) that I wasn’t expecting anything more than 10% change. However, the second version shows a much bigger reduction in `syscall.Syscall`. How is that possible? I expected it to be faster, but not affect the time spend reading file.The exclusion of fmt was unnecessary since the number of matches will be very small. But that is probably not relevant here. I have run it multiple times and made sure file is cached.
Attached are the profile SVGs. You can also see that an entire branch of the execution has disappeared in the faster/second version.
I do understand the second has avoided the allocation of string via scanner.Text(), however, the output of go build -gcflags "-m" give me the following
// First version
> go build -gcflags "-m" grep_simple_re.go
# command-line-arguments
./grep_simple_re.go:17: inlining call to bufio.NewScanner
./grep_simple_re.go:19: inlining call to (*bufio.Scanner).Text
./grep_simple_re.go:17: fp escapes to heap
./grep_simple_re.go:19: string(bufio.s·2.token) escapes to heap
./grep_simple_re.go:21: line escapes to heap
./grep_simple_re.go:17: main &bufio.Scanner literal does not escape
./grep_simple_re.go:21: main ... argument does not escape
<autogenerated>:1: leaking param: io.p
<autogenerated>:1: leaking param: .this
// Second version
> go build -gcflags "-m" grep_simple_re_bytes.go
# command-line-arguments
./grep_simple_re_bytes.go:18: inlining call to bufio.NewScanner
./grep_simple_re_bytes.go:20: inlining call to (*bufio.Scanner).Bytes
./grep_simple_re_bytes.go:16: fn escapes to heap
./grep_simple_re_bytes.go:16: err escapes to heap
./grep_simple_re_bytes.go:18: fp escapes to heap
./grep_simple_re_bytes.go:16: main ... argument does not escape
./grep_simple_re_bytes.go:18: main &bufio.Scanner literal does not escape
./grep_simple_re_bytes.go:24: main ([]byte)("\n") does not escape
<autogenerated>:1: leaking param: io.p
<autogenerated>:1: leaking param: .this
I can see "./grep_simple_re.go:21: line escapes to heap" could be a problem in the first version.
Here is the memory profiles of a run on 10million line 2.4 G file
$ go tool pprof ./grep_simple_re_mprofile /var/folders/bt/1mh2p2vx41lbnq3fz1n8qlxw0000gn/T/profile066323621/mem.pprof
Entering interactive mode (type "help" for commands)
(pprof) top10
86.37kB of 86.37kB total ( 100%)
Dropped 4 nodes (cum <= 0.43kB)
Showing top 10 nodes out of 23 (cum >= 43.89kB)
flat flat% sum% cum cum%
39.73kB 46.00% 46.00% 39.73kB 46.00% regexp.(*bitState).reset
16.30kB 18.87% 64.87% 16.30kB 18.87% bufio.(*Scanner).Scan
12.62kB 14.61% 79.48% 12.62kB 14.61% runtime.malg
9.04kB 10.47% 89.95% 17.45kB 20.21% runtime.allocm
4.52kB 5.23% 95.19% 4.52kB 5.23% runtime.rawstringtmp
4.16kB 4.81% 100% 4.16kB 4.81% regexp.progMachine
0 0% 100% 64.71kB 74.92% main.main
0 0% 100% 43.89kB 50.82% regexp.(*Regexp).MatchString
0 0% 100% 43.89kB 50.82% regexp.(*Regexp).doExecute
0 0% 100% 43.89kB 50.82% regexp.(*Regexp).doMatch
(pprof) quit
$ go tool pprof -alloc_space ./grep_simple_re_mprofile /var/folders/bt/1mh2p2vx41lbnq3fz1n8qlxw0000gn/T/profile066323621/mem.pprof
Entering interactive mode (type "help" for commands)
(pprof) top10
2.14GB of 2.14GB total ( 100%)
Dropped 22 nodes (cum <= 0.01GB)
flat flat% sum% cum cum%
2.14GB 100% 100% 2.14GB 100% runtime.rawstringtmp
0 0% 100% 2.14GB 100% main.main
0 0% 100% 2.14GB 100% runtime.goexit
0 0% 100% 2.14GB 100% runtime.main
0 0% 100% 2.14GB 100% runtime.slicebytetostring
The only explanation for such a large change is if it grew the stack 2.4G in size for the first case. The SVG attached seems to show something like that. Instead if it was heap allocation, why didn't it show up in the first pprof (memory profile) output above? Does 'escape to heap' not imply it will be allocated in heap?
Any call to re.Match or fmt.Println() escapes the string?
#### System details
```
go version go1.8 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/harry/code"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/bt/1mh2p2vx41lbnq3fz1n8qlxw0000gn/T/go-build737735845=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-L/usr/local/lib"
GOROOT/bin/go version: go version go1.8 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.8 X:framepointer
uname -v: Darwin Kernel Version 15.6.0: Mon Jan 9 23:07:29 PST 2017; root:xnu-3248.60.11.2.1~1/RELEASE_X86_64
ProductName: Mac OS X
ProductVersion: 10.11.6
BuildVersion: 15G1217
lldb --version: lldb-360.1.70
```
Thanks
--
Harry
As part of preparing an internal go talk to explain using strings vs bytes of the bufio.Scanner, I created two small samples https://play.golang.org/p/-TYycdHaPC and https://play.golang.org/p/L7W-jiaHdL , the only difference in the hot path is reducing the conversions from `[]byte` to `string` (later also avoids fmt module’s string conversions). Input being a 10 million line file. Match is only one line.
For the moment, ignore the fact that I am not checking for number of arguments, is doing unnecessary optimizations etc. I am trying to take a simple case to explain.
First version runs in 3 seconds, second in 2 seconds. For the slower version using `.Text()` 90+ percent of the time was in `syscall.Syscall` (under syscall.Read on the file) that I wasn’t expecting anything more than 10% change. However, the second version shows a much bigger reduction in `syscall.Syscall`. How is that possible? I expected it to be faster, but not affect the time spend reading file.The exclusion of fmt was unnecessary since the number of matches will be very small. But that is probably not relevant here. I have run it multiple times and made sure file is cached.
Attached are the profile SVGs. You can also see that an entire branch of the execution has disappeared in the faster/second version.
I do understand the second has avoided the allocation of string via scanner.Text(), however, the output of go build -gcflags "-m" give me the following
// First version
> go build -gcflags "-m" grep_simple_re.go
# command-line-arguments
./grep_simple_re.go:17: inlining call to bufio.NewScanner
./grep_simple_re.go:19: inlining call to (*bufio.Scanner).Text
./grep_simple_re.go:17: fp escapes to heap
./grep_simple_re.go:19: string(bufio.s·2.token) escapes to heap
./grep_simple_re.go:21: line escapes to heap
./grep_simple_re.go:17: main &bufio.Scanner literal does not escape
./grep_simple_re.go:21: main ... argument does not escape
<autogenerated>:1: leaking param: io.p
<autogenerated>:1: leaking param: .this
// Second version
> go build -gcflags "-m" grep_simple_re_bytes.go
# command-line-arguments
./grep_simple_re_bytes.go:18: inlining call to bufio.NewScanner
./grep_simple_re_bytes.go:20: inlining call to (*bufio.Scanner).Bytes
./grep_simple_re_bytes.go:16: fn escapes to heap
./grep_simple_re_bytes.go:16: err escapes to heap
./grep_simple_re_bytes.go:18: fp escapes to heap
./grep_simple_re_bytes.go:16: main ... argument does not escape
./grep_simple_re_bytes.go:18: main &bufio.Scanner literal does not escape
./grep_simple_re_bytes.go:24: main ([]byte)("\n") does not escape
<autogenerated>:1: leaking param: io.p
<autogenerated>:1: leaking param: .this
I can see "./grep_simple_re.go:21: line escapes to heap" could be a problem in the first version.
Here is the memory profiles of a run on 10million line 2.4 G file
$ go tool pprof ./grep_simple_re_mprofile /var/folders/bt/1mh2p2vx41lbnq3fz1n8qlxw0000gn/T/profile066323621/mem.pprof
Entering interactive mode (type "help" for commands)
(pprof) top10
86.37kB of 86.37kB total ( 100%)
Dropped 4 nodes (cum <= 0.43kB)
Showing top 10 nodes out of 23 (cum >= 43.89kB)
flat flat% sum% cum cum%
39.73kB 46.00% 46.00% 39.73kB 46.00% regexp.(*bitState).reset
16.30kB 18.87% 64.87% 16.30kB 18.87% bufio.(*Scanner).Scan
12.62kB 14.61% 79.48% 12.62kB 14.61% runtime.malg
9.04kB 10.47% 89.95% 17.45kB 20.21% runtime.allocm
4.52kB 5.23% 95.19% 4.52kB 5.23% runtime.rawstringtmp
4.16kB 4.81% 100% 4.16kB 4.81% regexp.progMachine
0 0% 100% 64.71kB 74.92% main.main
0 0% 100% 43.89kB 50.82% regexp.(*Regexp).MatchString
0 0% 100% 43.89kB 50.82% regexp.(*Regexp).doExecute
0 0% 100% 43.89kB 50.82% regexp.(*Regexp).doMatch
(pprof) quit
$ go tool pprof -alloc_space ./grep_simple_re_mprofile /var/folders/bt/1mh2p2vx41lbnq3fz1n8qlxw0000gn/T/profile066323621/mem.pprof
Entering interactive mode (type "help" for commands)
(pprof) top10
2.14GB of 2.14GB total ( 100%)
Dropped 22 nodes (cum <= 0.01GB)
flat flat% sum% cum cum%
2.14GB 100% 100% 2.14GB 100% runtime.rawstringtmp
0 0% 100% 2.14GB 100% main.main
0 0% 100% 2.14GB 100% runtime.goexit
0 0% 100% 2.14GB 100% runtime.main
0 0% 100% 2.14GB 100% runtime.slicebytetostring
The only explanation for such a large change is if it grew the stack 2.4G in size for the first case. The SVG attached seems to show something like that. Instead if it was heap allocation, why didn't it show up in the first pprof (memory profile) output above? Does 'escape to heap' not imply it will be allocated in heap?
Any call to re.Match or fmt.Println() escapes the string?
#### System details
```
go version go1.8 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/harry/code"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/bt/1mh2p2vx41lbnq3fz1n8qlxw0000gn/T/go-build737735845=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-L/usr/local/lib"
GOROOT/bin/go version: go version go1.8 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.8 X:framepointer
uname -v: Darwin Kernel Version 15.6.0: Mon Jan 9 23:07:29 PST 2017; root:xnu-3248.60.11.2.1~1/RELEASE_X86_64
ProductName: Mac OS X
ProductVersion: 10.11.6
BuildVersion: 15G1217
lldb --version: lldb-360.1.70
```
Thanks
--
Harry
peterGo
Mar 21, 2017, 2:40:29 PM3/21/17
to golang-nuts
Harry,
To be meaningful, benchmarks must be reproducible.
You use some file with 10 million lines and 2.4 gigabytes.
grepin.go (https://play.golang.org/p/YGRAJ6dEVn) is a program that generates known input data.
Your programs had variations other than Bytes() and Text().
grepbytes.go (https://play.golang.org/p/RpKBJjHOeJ) and greptext.go (https://play.golang.org/p/XzW6IBueyy) are identical except for necessary Bytes() and Text() differences. Text() converts Bytes() to string.
pprof uses 100 Hz samples to estimate population values. Three and two second runtimes produce small samples. The grepin.go program adjusts the file size by a multiplier to produce a larger number of samples on my machine.
The pprof estimates for syscall.Syscall are 103.40ms for Bytes and 106.20ms for Text, they are equal within measurement error.
You said: "First version runs in 3 seconds, second in 2 seconds. For the slower version using `.Text()` 90+ percent of the time was in `syscall.Syscall` (under syscall.Read on the file) that I wasn’t expecting anything more than 10% change. However, the second version shows a much bigger reduction in `syscall.Syscall`. How is that possible? I expected it to be faster, but not affect the time spend reading file." You didn't provide pprof cpu top output. Your attached profile SVG files are unreadable.
So I'm puzzled that you are puzzled.
$ go version
go version devel +24dc8c6 Tue Mar 21 16:03:12 2017 +0000 linux/amd64
$ go run grepin.go
40000000 9600000000
$ go build grepbytes.go && time ./grepbytes XxX /tmp/grepin.txt
2017/03/21 13:09:38 profile: cpu profiling enabled, /tmp/profile656604512/cpu.pprof
40000000 9600000000
2017/03/21 13:10:16 profile: cpu profiling disabled, /tmp/profile656604512/cpu.pprof
real 0m38.567s
user 0m25.016s
sys 0m10.744s
$ go tool pprof ./grepbytes /tmp/profile656604512/cpu.pprof
File: grepbytes
Type: cpu
Time: Mar 21, 2017 at 1:09pm (EDT)
Duration: 38.55s, Total samples = 344.60ms ( 0.89%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 325.40ms, 94.43% of 344.60ms total
Dropped 36 nodes (cum <= 1.72ms)
Showing top 20 nodes out of 30
To be meaningful, benchmarks must be reproducible.
You use some file with 10 million lines and 2.4 gigabytes.
grepin.go (https://play.golang.org/p/YGRAJ6dEVn) is a program that generates known input data.
Your programs had variations other than Bytes() and Text().
grepbytes.go (https://play.golang.org/p/RpKBJjHOeJ) and greptext.go (https://play.golang.org/p/XzW6IBueyy) are identical except for necessary Bytes() and Text() differences. Text() converts Bytes() to string.
pprof uses 100 Hz samples to estimate population values. Three and two second runtimes produce small samples. The grepin.go program adjusts the file size by a multiplier to produce a larger number of samples on my machine.
The pprof estimates for syscall.Syscall are 103.40ms for Bytes and 106.20ms for Text, they are equal within measurement error.
You said: "First version runs in 3 seconds, second in 2 seconds. For the slower version using `.Text()` 90+ percent of the time was in `syscall.Syscall` (under syscall.Read on the file) that I wasn’t expecting anything more than 10% change. However, the second version shows a much bigger reduction in `syscall.Syscall`. How is that possible? I expected it to be faster, but not affect the time spend reading file." You didn't provide pprof cpu top output. Your attached profile SVG files are unreadable.
So I'm puzzled that you are puzzled.
$ go version
go version devel +24dc8c6 Tue Mar 21 16:03:12 2017 +0000 linux/amd64
$ go run grepin.go
40000000 9600000000
$ go build grepbytes.go && time ./grepbytes XxX /tmp/grepin.txt
2017/03/21 13:09:38 profile: cpu profiling enabled, /tmp/profile656604512/cpu.pprof
40000000 9600000000
2017/03/21 13:10:16 profile: cpu profiling disabled, /tmp/profile656604512/cpu.pprof
real 0m38.567s
user 0m25.016s
sys 0m10.744s
$ go tool pprof ./grepbytes /tmp/profile656604512/cpu.pprof
File: grepbytes
Type: cpu
Time: Mar 21, 2017 at 1:09pm (EDT)
Duration: 38.55s, Total samples = 344.60ms ( 0.89%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 325.40ms, 94.43% of 344.60ms total
Dropped 36 nodes (cum <= 1.72ms)
Showing top 20 nodes out of 30
flat flat% sum% cum cum%
103.40ms 30.01% 30.01% 109.20ms 31.69% syscall.Syscall /home/peter/go/src/syscall/asm_linux_amd64.s
42.70ms 12.39% 42.40% 42.70ms 12.39% runtime.indexbytebody /home/peter/go/src/runtime/asm_amd64.s
27.20ms 7.89% 50.29% 27.20ms 7.89% sync.(*Mutex).Lock /home/peter/go/src/sync/mutex.go
25ms 7.25% 57.54% 25ms 7.25% sync.(*Mutex).Unlock /home/peter/go/src/sync/mutex.go
18.90ms 5.48% 63.03% 175.60ms 50.96% bufio.(*Scanner).Scan /home/peter/go/src/bufio/scan.go
12.70ms 3.69% 66.72% 68.80ms 19.97% regexp.(*machine).backtrack /home/peter/go/src/regexp/backtrack.go
12.70ms 3.69% 70.40% 12.70ms 3.69% runtime.memclrNoHeapPointers /home/peter/go/src/runtime/memclr_amd64.s
10.50ms 3.05% 73.45% 33.50ms 9.72% bufio.ScanLines /home/peter/go/src/bufio/scan.go
10.20ms 2.96% 76.41% 145.70ms 42.28% regexp.(*Regexp).doExecute /home/peter/go/src/regexp/exec.go
9ms 2.61% 79.02% 154.70ms 44.89% regexp.(*Regexp).doMatch /home/peter/go/src/regexp/exec.go
8.50ms 2.47% 81.49% 31.20ms 9.05% bytes.Index /home/peter/go/src/bytes/bytes_amd64.go
7.70ms 2.23% 83.72% 32.90ms 9.55% regexp.(*Regexp).put /home/peter/go/src/regexp/regexp.go
6.80ms 1.97% 85.69% 33.80ms 9.81% regexp.(*Regexp).get /home/peter/go/src/regexp/regexp.go
6.70ms 1.94% 87.64% 161.40ms 46.84% regexp.(*Regexp).Match /home/peter/go/src/regexp/regexp.go
6.10ms 1.77% 89.41% 18.80ms 5.46% regexp.(*bitState).reset /home/peter/go/src/regexp/backtrack.go
5.60ms 1.63% 91.03% 36.80ms 10.68% regexp.(*inputBytes).index /home/peter/go/src/regexp/regexp.go
5.50ms 1.60% 92.63% 342.50ms 99.39% main.main /home/peter/gopath/src/nuts/prof/grepbytes.go
3ms 0.87% 93.50% 3ms 0.87% bytes.IndexByte /home/peter/go/src/runtime/asm_amd64.s
1.70ms 0.49% 93.99% 2.40ms 0.7% runtime.reentersyscall /home/peter/go/src/runtime/proc.go
1.50ms 0.44% 94.43% 121.70ms 35.32% os.(*File).read /home/peter/go/src/os/file_unix.go
(pprof) quit
$ go build greptext.go && time ./greptext XxX /tmp/grepin.txt
2017/03/21 13:15:26 profile: cpu profiling enabled, /tmp/profile069788137/cpu.pprof
40000000 9600000000
2017/03/21 13:16:19 profile: cpu profiling disabled, /tmp/profile069788137/cpu.pprof
real 0m53.217s
user 0m48.280s
sys 0m11.976s
$ go tool pprof ./greptext /tmp/profile069788137/cpu.pprof
File: greptext
Type: cpu
Time: Mar 21, 2017 at 1:15pm (EDT)
Duration: 53.19s, Total samples = 584ms ( 1.10%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 433.10ms, 74.16% of 584ms total
Dropped 149 nodes (cum <= 2.92ms)
Showing top 20 nodes out of 80
42.70ms 12.39% 42.40% 42.70ms 12.39% runtime.indexbytebody /home/peter/go/src/runtime/asm_amd64.s
27.20ms 7.89% 50.29% 27.20ms 7.89% sync.(*Mutex).Lock /home/peter/go/src/sync/mutex.go
25ms 7.25% 57.54% 25ms 7.25% sync.(*Mutex).Unlock /home/peter/go/src/sync/mutex.go
18.90ms 5.48% 63.03% 175.60ms 50.96% bufio.(*Scanner).Scan /home/peter/go/src/bufio/scan.go
12.70ms 3.69% 66.72% 68.80ms 19.97% regexp.(*machine).backtrack /home/peter/go/src/regexp/backtrack.go
12.70ms 3.69% 70.40% 12.70ms 3.69% runtime.memclrNoHeapPointers /home/peter/go/src/runtime/memclr_amd64.s
10.50ms 3.05% 73.45% 33.50ms 9.72% bufio.ScanLines /home/peter/go/src/bufio/scan.go
10.20ms 2.96% 76.41% 145.70ms 42.28% regexp.(*Regexp).doExecute /home/peter/go/src/regexp/exec.go
9ms 2.61% 79.02% 154.70ms 44.89% regexp.(*Regexp).doMatch /home/peter/go/src/regexp/exec.go
8.50ms 2.47% 81.49% 31.20ms 9.05% bytes.Index /home/peter/go/src/bytes/bytes_amd64.go
7.70ms 2.23% 83.72% 32.90ms 9.55% regexp.(*Regexp).put /home/peter/go/src/regexp/regexp.go
6.80ms 1.97% 85.69% 33.80ms 9.81% regexp.(*Regexp).get /home/peter/go/src/regexp/regexp.go
6.70ms 1.94% 87.64% 161.40ms 46.84% regexp.(*Regexp).Match /home/peter/go/src/regexp/regexp.go
6.10ms 1.77% 89.41% 18.80ms 5.46% regexp.(*bitState).reset /home/peter/go/src/regexp/backtrack.go
5.60ms 1.63% 91.03% 36.80ms 10.68% regexp.(*inputBytes).index /home/peter/go/src/regexp/regexp.go
5.50ms 1.60% 92.63% 342.50ms 99.39% main.main /home/peter/gopath/src/nuts/prof/grepbytes.go
3ms 0.87% 93.50% 3ms 0.87% bytes.IndexByte /home/peter/go/src/runtime/asm_amd64.s
1.70ms 0.49% 93.99% 2.40ms 0.7% runtime.reentersyscall /home/peter/go/src/runtime/proc.go
1.50ms 0.44% 94.43% 121.70ms 35.32% os.(*File).read /home/peter/go/src/os/file_unix.go
(pprof) quit
$ go build greptext.go && time ./greptext XxX /tmp/grepin.txt
2017/03/21 13:15:26 profile: cpu profiling enabled, /tmp/profile069788137/cpu.pprof
40000000 9600000000
2017/03/21 13:16:19 profile: cpu profiling disabled, /tmp/profile069788137/cpu.pprof
real 0m53.217s
user 0m48.280s
sys 0m11.976s
$ go tool pprof ./greptext /tmp/profile069788137/cpu.pprof
File: greptext
Type: cpu
Time: Mar 21, 2017 at 1:15pm (EDT)
Duration: 53.19s, Total samples = 584ms ( 1.10%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top20
Showing nodes accounting for 433.10ms, 74.16% of 584ms total
Dropped 149 nodes (cum <= 2.92ms)
Showing top 20 nodes out of 80
flat flat% sum% cum cum%
106.20ms 18.18% 18.18% 115.40ms 19.76% syscall.Syscall /home/peter/go/src/syscall/asm_linux_amd64.s
47.70ms 8.17% 26.35% 47.70ms 8.17% runtime.indexbytebody /home/peter/go/src/runtime/asm_amd64.s
31ms 5.31% 31.66% 31ms 5.31% runtime.memclrNoHeapPointers /home/peter/go/src/runtime/memclr_amd64.s
30.90ms 5.29% 36.95% 30.90ms 5.29% sync.(*Mutex).Lock /home/peter/go/src/sync/mutex.go
29.90ms 5.12% 42.07% 29.90ms 5.12% sync.(*Mutex).Unlock /home/peter/go/src/sync/mutex.go
24.90ms 4.26% 46.34% 111.80ms 19.14% runtime.mallocgc /home/peter/go/src/runtime/malloc.go
18.50ms 3.17% 49.50% 191.30ms 32.76% bufio.(*Scanner).Scan /home/peter/go/src/bufio/scan.go
18.50ms 3.17% 52.67% 18.50ms 3.17% runtime.memmove /home/peter/go/src/runtime/memmove_amd64.s
16.10ms 2.76% 55.43% 19.90ms 3.41% runtime.scanobject /home/peter/go/src/runtime/mgcmark.go
13.60ms 2.33% 57.76% 13.60ms 2.33% runtime.nextFreeFast /home/peter/go/src/runtime/malloc.go
12.70ms 2.17% 59.93% 72.30ms 12.38% regexp.(*machine).backtrack /home/peter/go/src/regexp/backtrack.go
12.60ms 2.16% 62.09% 179.10ms 30.67% regexp.(*Regexp).doMatch /home/peter/go/src/regexp/exec.go
11.60ms 1.99% 64.08% 166.50ms 28.51% regexp.(*Regexp).doExecute /home/peter/go/src/regexp/exec.go
11.30ms 1.93% 66.01% 37ms 6.34% bufio.ScanLines /home/peter/go/src/bufio/scan.go
8.30ms 1.42% 67.43% 40.10ms 6.87% regexp.(*Regexp).put /home/peter/go/src/regexp/regexp.go
8.30ms 1.42% 68.85% 33.20ms 5.68% strings.Index /home/peter/go/src/strings/strings_amd64.go
7.90ms 1.35% 70.21% 18.60ms 3.18% regexp.(*bitState).reset /home/peter/go/src/regexp/backtrack.go
7.90ms 1.35% 71.56% 150.90ms 25.84% runtime.slicebytetostring /home/peter/go/src/runtime/string.go
7.60ms 1.30% 72.86% 7.60ms 1.30% runtime.mallocgc /home/peter/go/src/runtime/mbitmap.go
7.60ms 1.30% 74.16% 8.90ms 1.52% runtime.scanblock /home/peter/go/src/runtime/mgcmark.go
(pprof) quit
Peter
47.70ms 8.17% 26.35% 47.70ms 8.17% runtime.indexbytebody /home/peter/go/src/runtime/asm_amd64.s
31ms 5.31% 31.66% 31ms 5.31% runtime.memclrNoHeapPointers /home/peter/go/src/runtime/memclr_amd64.s
30.90ms 5.29% 36.95% 30.90ms 5.29% sync.(*Mutex).Lock /home/peter/go/src/sync/mutex.go
29.90ms 5.12% 42.07% 29.90ms 5.12% sync.(*Mutex).Unlock /home/peter/go/src/sync/mutex.go
24.90ms 4.26% 46.34% 111.80ms 19.14% runtime.mallocgc /home/peter/go/src/runtime/malloc.go
18.50ms 3.17% 49.50% 191.30ms 32.76% bufio.(*Scanner).Scan /home/peter/go/src/bufio/scan.go
18.50ms 3.17% 52.67% 18.50ms 3.17% runtime.memmove /home/peter/go/src/runtime/memmove_amd64.s
16.10ms 2.76% 55.43% 19.90ms 3.41% runtime.scanobject /home/peter/go/src/runtime/mgcmark.go
13.60ms 2.33% 57.76% 13.60ms 2.33% runtime.nextFreeFast /home/peter/go/src/runtime/malloc.go
12.70ms 2.17% 59.93% 72.30ms 12.38% regexp.(*machine).backtrack /home/peter/go/src/regexp/backtrack.go
12.60ms 2.16% 62.09% 179.10ms 30.67% regexp.(*Regexp).doMatch /home/peter/go/src/regexp/exec.go
11.60ms 1.99% 64.08% 166.50ms 28.51% regexp.(*Regexp).doExecute /home/peter/go/src/regexp/exec.go
11.30ms 1.93% 66.01% 37ms 6.34% bufio.ScanLines /home/peter/go/src/bufio/scan.go
8.30ms 1.42% 67.43% 40.10ms 6.87% regexp.(*Regexp).put /home/peter/go/src/regexp/regexp.go
8.30ms 1.42% 68.85% 33.20ms 5.68% strings.Index /home/peter/go/src/strings/strings_amd64.go
7.90ms 1.35% 70.21% 18.60ms 3.18% regexp.(*bitState).reset /home/peter/go/src/regexp/backtrack.go
7.90ms 1.35% 71.56% 150.90ms 25.84% runtime.slicebytetostring /home/peter/go/src/runtime/string.go
7.60ms 1.30% 72.86% 7.60ms 1.30% runtime.mallocgc /home/peter/go/src/runtime/mbitmap.go
7.60ms 1.30% 74.16% 8.90ms 1.52% runtime.scanblock /home/peter/go/src/runtime/mgcmark.go
(pprof) quit
Peter
peterGo
Mar 21, 2017, 2:46:39 PM3/21/17
to golang-nuts
s/greptext.go (https://play.golang.org/p/XzW6IBueyy)/greptext.go (https://play.golang.org/p/-C9bVEJ2QP))/
Reply all
Reply to author
Forward
0 new messages