Skip to content

Instantly share code, notes, and snippets.

@zsfelfoldi

zsfelfoldi/prof_old

Created April 10, 2016 17:36
Show Gist options
  • Save zsfelfoldi/a26014c2640fe814633968669636a2bd to your computer and use it in GitHub Desktop.
Save zsfelfoldi/a26014c2640fe814633968669636a2bd to your computer and use it in GitHub Desktop.
Download ZIP
Raw
prof_old
Benchmarking 100000 consecutive header reads from an existing "old style" database (found at DefaultDataDir/_old):
(note that the database being cached into memory either by leveldb or by the OS affects this test dramatically; this test has been carried out after a fresh system restart)
fefe@Fefe-ThinkPad-SL500:~/go-ethereum$ godep go test -v ./core -bench BenchmarkReadChain_old_header_100k -run XXX -cpuprofile old.prof
PASS
BenchmarkReadChain_old_header_100k-2 1 539808334396 ns/op
ok _/home/fefe/go-ethereum/core 540.260s
CPU profile top 100 nodes (both flat and cumulative are listed):
(note that the total time profiled is only about 4% of the running time so the time values cannot be compared directly)
fefe@Fefe-ThinkPad-SL500:~/go-ethereum$ go tool pprof core.test.old old.prof
Entering interactive mode (type "help" for commands)
(pprof) top 100
18.18s of 21s total (86.57%)
Dropped 180 nodes (cum <= 0.10s)
Showing top 100 nodes out of 106 (cum >= 0.12s)
flat flat% sum% cum cum%
4.42s 21.05% 21.05% 4.50s 21.43% syscall.Syscall6
3.48s 16.57% 37.62% 3.48s 16.57% runtime.usleep
1.63s 7.76% 45.38% 1.63s 7.76% ExternalCode
1.56s 7.43% 52.81% 1.56s 7.43% hash/crc32.update
0.80s 3.81% 56.62% 1.06s 5.05% github.com/golang/snappy.Decode
0.53s 2.52% 59.14% 0.56s 2.67% runtime.mallocgc
0.44s 2.10% 61.24% 0.44s 2.10% runtime.memmove
0.34s 1.62% 62.86% 0.69s 3.29% github.com/syndtr/goleveldb/leveldb.func·028
0.26s 1.24% 64.10% 0.40s 1.90% github.com/syndtr/goleveldb/leveldb/cache.(*mBucket).get
0.21s 1.00% 65.10% 0.84s 4.00% github.com/syndtr/goleveldb/leveldb.(*iComparer).Compare
0.21s 1.00% 66.10% 0.21s 1.00% runtime.futex
0.20s 0.95% 67.05% 0.20s 0.95% runtime.newdefer
0.19s 0.9% 67.95% 0.19s 0.9% runtime.memclr
0.18s 0.86% 68.81% 0.18s 0.86% runtime.cmpbody
0.17s 0.81% 69.62% 0.17s 0.81% encoding/binary.Uvarint
0.17s 0.81% 70.43% 0.17s 0.81% github.com/syndtr/goleveldb/leveldb.internalKey.assert
0.17s 0.81% 71.24% 0.17s 0.81% runtime.writebarrierptr
0.16s 0.76% 72.00% 0.41s 1.95% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Next
0.14s 0.67% 72.67% 0.14s 0.67% MCentral_Grow
0.14s 0.67% 73.33% 0.14s 0.67% sync/atomic.AddUint32
0.13s 0.62% 73.95% 0.39s 1.86% github.com/syndtr/goleveldb/leveldb/comparer.(*bytesComparer).Compare
0.13s 0.62% 74.57% 0.13s 0.62% runtime.releasem
0.12s 0.57% 75.14% 0.29s 1.38% github.com/syndtr/goleveldb/leveldb.internalKey.ukey
0.12s 0.57% 75.71% 0.36s 1.71% runtime.deferreturn
0.12s 0.57% 76.29% 0.12s 0.57% runtime.memhash
0.11s 0.52% 76.81% 1.20s 5.71% sort.Search
0.10s 0.48% 77.29% 0.40s 1.90% github.com/syndtr/goleveldb/leveldb/table.func·001
0.10s 0.48% 77.76% 0.54s 2.57% runtime.newobject
0.09s 0.43% 78.19% 0.18s 0.86% runtime.growslice
0.07s 0.33% 78.52% 0.24s 1.14% github.com/ethereum/go-ethereum/rlp.(*Stream).Kind
0.07s 0.33% 78.86% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb/table.(*block).entry
0.07s 0.33% 79.19% 1.15s 5.48% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Seek
0.07s 0.33% 79.52% 4.57s 21.76% os.(*File).pread
0.07s 0.33% 79.86% 0.17s 0.81% runtime.makeslice
0.06s 0.29% 80.14% 0.16s 0.76% github.com/ethereum/go-ethereum/rlp.(*Stream).readFull
0.06s 0.29% 80.43% 7.52s 35.81% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readRawBlock
0.06s 0.29% 80.71% 0.20s 0.95% runtime.deferproc
0.06s 0.29% 81.00% 0.12s 0.57% runtime.freedefer
0.06s 0.29% 81.29% 0.14s 0.67% runtime.mapaccess2
0.05s 0.24% 81.52% 8.69s 41.38% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Get
0.04s 0.19% 81.71% 2.17s 10.33% _/home/fefe/go-ethereum/core.GetCanonicalHash
0.04s 0.19% 81.90% 0.41s 1.95% github.com/ethereum/go-ethereum/rlp.decodeByteArray
0.04s 0.19% 82.10% 1.03s 4.90% github.com/ethereum/go-ethereum/rlp.func·005
0.04s 0.19% 82.29% 0.26s 1.24% github.com/syndtr/goleveldb/leveldb/comparer.bytesComparer.Compare
0.04s 0.19% 82.48% 0.15s 0.71% github.com/syndtr/goleveldb/leveldb/table.(*Reader).newBlockIter
0.04s 0.19% 82.67% 8.44s 40.19% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlockCached
0.04s 0.19% 82.86% 0.17s 0.81% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Get
0.04s 0.19% 83.05% 0.16s 0.76% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Put
0.04s 0.19% 83.24% 0.15s 0.71% runtime.nilinterhash
0.03s 0.14% 83.38% 12.05s 57.38% _/home/fefe/go-ethereum/core.(*HeaderChain).getHeader
0.03s 0.14% 83.52% 12.16s 57.90% github.com/ethereum/go-ethereum/ethdb.(*LDBDatabase).Get
0.03s 0.14% 83.67% 11.90s 56.67% github.com/syndtr/goleveldb/leveldb.(*DB).get
0.03s 0.14% 83.81% 11.49s 54.71% github.com/syndtr/goleveldb/leveldb.(*version).walkOverlapping
0.03s 0.14% 83.95% 10.60s 50.48% github.com/syndtr/goleveldb/leveldb.func·032
0.03s 0.14% 84.10% 0.35s 1.67% github.com/syndtr/goleveldb/leveldb/cache.(*lru).Promote
0.03s 0.14% 84.24% 0.46s 2.19% github.com/syndtr/goleveldb/leveldb/table.(*block).seek
0.03s 0.14% 84.38% 0.14s 0.67% sync.(*Mutex).Lock
0.02s 0.095% 84.48% 0.18s 0.86% github.com/ethereum/go-ethereum/rlp.(*Stream).Bytes
0.02s 0.095% 84.57% 0.11s 0.52% github.com/ethereum/go-ethereum/rlp.(*Stream).List
0.02s 0.095% 84.67% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb.(*DB).acquireSnapshot
0.02s 0.095% 84.76% 0.34s 1.62% github.com/syndtr/goleveldb/leveldb.(*tOps).open
0.02s 0.095% 84.86% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb.memGet
0.02s 0.095% 84.95% 0.16s 0.76% github.com/syndtr/goleveldb/leveldb/cache.(*Node).unrefLocked
0.02s 0.095% 85.05% 0.12s 0.57% github.com/syndtr/goleveldb/leveldb/cache.(*mBucket).delete
0.02s 0.095% 85.14% 0.11s 0.52% github.com/syndtr/goleveldb/leveldb/memdb.(*DB).Find
0.02s 0.095% 85.24% 10.14s 48.29% github.com/syndtr/goleveldb/leveldb/table.(*Reader).find
0.02s 0.095% 85.33% 8.19s 39.00% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getDataIter
0.02s 0.095% 85.43% 0.12s 0.57% reflect.valueInterface
0.02s 0.095% 85.52% 0.20s 0.95% runtime.cmpbytes
0.01s 0.048% 85.57% 14.26s 67.90% _/home/fefe/go-ethereum/core.(*BlockChain).GetHeaderByNumber
0.01s 0.048% 85.62% 10.19s 48.52% _/home/fefe/go-ethereum/core.GetHeaderRLP
0.01s 0.048% 85.67% 14.33s 68.24% _/home/fefe/go-ethereum/core.benchReadChain
0.01s 0.048% 85.71% 1.14s 5.43% github.com/ethereum/go-ethereum/rlp.(*Stream).Decode
0.01s 0.048% 85.76% 0.16s 0.76% github.com/ethereum/go-ethereum/rlp.(*Stream).readKind
0.01s 0.048% 85.81% 0.30s 1.43% github.com/ethereum/go-ethereum/rlp.decodeBigInt
0.01s 0.048% 85.86% 0.34s 1.62% github.com/hashicorp/golang-lru.(*Cache).Add
0.01s 0.048% 85.90% 0.28s 1.33% github.com/hashicorp/golang-lru/simplelru.(*LRU).Add
0.01s 0.048% 85.95% 12.13s 57.76% github.com/syndtr/goleveldb/leveldb.(*DB).Get
0.01s 0.048% 86.00% 10.53s 50.14% github.com/syndtr/goleveldb/leveldb.(*tOps).find
0.01s 0.048% 86.05% 11.50s 54.76% github.com/syndtr/goleveldb/leveldb.(*version).get
0.01s 0.048% 86.10% 0.78s 3.71% github.com/syndtr/goleveldb/leveldb.tFiles.searchMax
0.01s 0.048% 86.14% 0.19s 0.9% github.com/syndtr/goleveldb/leveldb/cache.(*Handle).Release
0.01s 0.048% 86.19% 8.38s 39.90% github.com/syndtr/goleveldb/leveldb/cache.(*NamespaceGetter).Get
0.01s 0.048% 86.24% 10.15s 48.33% github.com/syndtr/goleveldb/leveldb/table.(*Reader).Find
0.01s 0.048% 86.29% 0.34s 1.62% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getIndexBlock
0.01s 0.048% 86.33% 7.58s 36.10% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlock
0.01s 0.048% 86.38% 7.56s 36.00% github.com/syndtr/goleveldb/leveldb/table.func·003
0.01s 0.048% 86.43% 1.58s 7.52% github.com/syndtr/goleveldb/leveldb/util.CRC.Update
0.01s 0.048% 86.48% 1.59s 7.57% github.com/syndtr/goleveldb/leveldb/util.NewCRC
0.01s 0.048% 86.52% 1.57s 7.48% hash/crc32.Update
0.01s 0.048% 86.57% 4.58s 21.81% os.(*File).ReadAt
0 0% 86.57% 6.59s 31.38% System
0 0% 86.57% 14.25s 67.86% _/home/fefe/go-ethereum/core.(*HeaderChain).GetHeaderByNumber
0 0% 86.57% 14.33s 68.24% _/home/fefe/go-ethereum/core.BenchmarkReadChain_old_header_100k
0 0% 86.57% 11.50s 54.76% _/home/fefe/go-ethereum/core.GetHeader
0 0% 86.57% 1.20s 5.71% github.com/ethereum/go-ethereum/rlp.Decode
0 0% 86.57% 0.11s 0.52% github.com/ethereum/go-ethereum/rlp.decodeByteSlice
0 0% 86.57% 0.12s 0.57% github.com/hashicorp/golang-lru.(*Cache).Get
0 0% 86.57% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb.func·030
0 0% 86.57% 0.12s 0.57% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).delete
(pprof)
(pprof)
(pprof)
(pprof) top 100 -cum
17.94s of 21s total (85.43%)
Dropped 180 nodes (cum <= 0.10s)
Showing top 100 nodes out of 106 (cum >= 0.12s)
flat flat% sum% cum cum%
0 0% 0% 14.33s 68.24% _/home/fefe/go-ethereum/core.BenchmarkReadChain_old_header_100k
0.01s 0.048% 0.048% 14.33s 68.24% _/home/fefe/go-ethereum/core.benchReadChain
0 0% 0.048% 14.33s 68.24% runtime.goexit
0 0% 0.048% 14.33s 68.24% testing.(*B).launch
0 0% 0.048% 14.33s 68.24% testing.(*B).runN
0.01s 0.048% 0.095% 14.26s 67.90% _/home/fefe/go-ethereum/core.(*BlockChain).GetHeaderByNumber
0 0% 0.095% 14.25s 67.86% _/home/fefe/go-ethereum/core.(*HeaderChain).GetHeaderByNumber
0.03s 0.14% 0.24% 12.16s 57.90% github.com/ethereum/go-ethereum/ethdb.(*LDBDatabase).Get
0.01s 0.048% 0.29% 12.13s 57.76% github.com/syndtr/goleveldb/leveldb.(*DB).Get
0.03s 0.14% 0.43% 12.05s 57.38% _/home/fefe/go-ethereum/core.(*HeaderChain).getHeader
0.03s 0.14% 0.57% 11.90s 56.67% github.com/syndtr/goleveldb/leveldb.(*DB).get
0 0% 0.57% 11.50s 54.76% _/home/fefe/go-ethereum/core.GetHeader
0.01s 0.048% 0.62% 11.50s 54.76% github.com/syndtr/goleveldb/leveldb.(*version).get
0.03s 0.14% 0.76% 11.49s 54.71% github.com/syndtr/goleveldb/leveldb.(*version).walkOverlapping
0.03s 0.14% 0.9% 10.60s 50.48% github.com/syndtr/goleveldb/leveldb.func·032
0.01s 0.048% 0.95% 10.53s 50.14% github.com/syndtr/goleveldb/leveldb.(*tOps).find
0.01s 0.048% 1.00% 10.19s 48.52% _/home/fefe/go-ethereum/core.GetHeaderRLP
0.01s 0.048% 1.05% 10.15s 48.33% github.com/syndtr/goleveldb/leveldb/table.(*Reader).Find
0.02s 0.095% 1.14% 10.14s 48.29% github.com/syndtr/goleveldb/leveldb/table.(*Reader).find
0.05s 0.24% 1.38% 8.69s 41.38% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Get
0.04s 0.19% 1.57% 8.44s 40.19% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlockCached
0.01s 0.048% 1.62% 8.38s 39.90% github.com/syndtr/goleveldb/leveldb/cache.(*NamespaceGetter).Get
0.02s 0.095% 1.71% 8.19s 39.00% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getDataIter
0.01s 0.048% 1.76% 7.58s 36.10% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlock
0.01s 0.048% 1.81% 7.56s 36.00% github.com/syndtr/goleveldb/leveldb/table.func·003
0.06s 0.29% 2.10% 7.52s 35.81% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readRawBlock
0 0% 2.10% 6.59s 31.38% System
0.01s 0.048% 2.14% 4.58s 21.81% os.(*File).ReadAt
0.07s 0.33% 2.48% 4.57s 21.76% os.(*File).pread
0 0% 2.48% 4.50s 21.43% syscall.Pread
4.42s 21.05% 23.52% 4.50s 21.43% syscall.Syscall6
3.48s 16.57% 40.10% 3.48s 16.57% runtime.usleep
0.04s 0.19% 40.29% 2.17s 10.33% _/home/fefe/go-ethereum/core.GetCanonicalHash
1.63s 7.76% 48.05% 1.63s 7.76% ExternalCode
0.01s 0.048% 48.10% 1.59s 7.57% github.com/syndtr/goleveldb/leveldb/util.NewCRC
0.01s 0.048% 48.14% 1.58s 7.52% github.com/syndtr/goleveldb/leveldb/util.CRC.Update
0.01s 0.048% 48.19% 1.57s 7.48% hash/crc32.Update
1.56s 7.43% 55.62% 1.56s 7.43% hash/crc32.update
0 0% 55.62% 1.56s 7.43% hash/crc32.updateCastagnoli
0 0% 55.62% 1.20s 5.71% github.com/ethereum/go-ethereum/rlp.Decode
0.11s 0.52% 56.14% 1.20s 5.71% sort.Search
0.07s 0.33% 56.48% 1.15s 5.48% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Seek
0.01s 0.048% 56.52% 1.14s 5.43% github.com/ethereum/go-ethereum/rlp.(*Stream).Decode
0.80s 3.81% 60.33% 1.06s 5.05% github.com/golang/snappy.Decode
0.04s 0.19% 60.52% 1.03s 4.90% github.com/ethereum/go-ethereum/rlp.func·005
0.21s 1.00% 61.52% 0.84s 4.00% github.com/syndtr/goleveldb/leveldb.(*iComparer).Compare
0.01s 0.048% 61.57% 0.78s 3.71% github.com/syndtr/goleveldb/leveldb.tFiles.searchMax
0.34s 1.62% 63.19% 0.69s 3.29% github.com/syndtr/goleveldb/leveldb.func·028
0.53s 2.52% 65.71% 0.56s 2.67% runtime.mallocgc
0.10s 0.48% 66.19% 0.54s 2.57% runtime.newobject
0.03s 0.14% 66.33% 0.46s 2.19% github.com/syndtr/goleveldb/leveldb/table.(*block).seek
0.44s 2.10% 68.43% 0.44s 2.10% runtime.memmove
0.04s 0.19% 68.62% 0.41s 1.95% github.com/ethereum/go-ethereum/rlp.decodeByteArray
0.16s 0.76% 69.38% 0.41s 1.95% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Next
0.26s 1.24% 70.62% 0.40s 1.90% github.com/syndtr/goleveldb/leveldb/cache.(*mBucket).get
0.10s 0.48% 71.10% 0.40s 1.90% github.com/syndtr/goleveldb/leveldb/table.func·001
0.13s 0.62% 71.71% 0.39s 1.86% github.com/syndtr/goleveldb/leveldb/comparer.(*bytesComparer).Compare
0.12s 0.57% 72.29% 0.36s 1.71% runtime.deferreturn
0.03s 0.14% 72.43% 0.35s 1.67% github.com/syndtr/goleveldb/leveldb/cache.(*lru).Promote
0.01s 0.048% 72.48% 0.34s 1.62% github.com/hashicorp/golang-lru.(*Cache).Add
0.02s 0.095% 72.57% 0.34s 1.62% github.com/syndtr/goleveldb/leveldb.(*tOps).open
0.01s 0.048% 72.62% 0.34s 1.62% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getIndexBlock
0.01s 0.048% 72.67% 0.30s 1.43% github.com/ethereum/go-ethereum/rlp.decodeBigInt
0.12s 0.57% 73.24% 0.29s 1.38% github.com/syndtr/goleveldb/leveldb.internalKey.ukey
0.01s 0.048% 73.29% 0.28s 1.33% github.com/hashicorp/golang-lru/simplelru.(*LRU).Add
0.04s 0.19% 73.48% 0.26s 1.24% github.com/syndtr/goleveldb/leveldb/comparer.bytesComparer.Compare
0.07s 0.33% 73.81% 0.24s 1.14% github.com/ethereum/go-ethereum/rlp.(*Stream).Kind
0.21s 1.00% 74.81% 0.21s 1.00% runtime.futex
0.02s 0.095% 74.90% 0.20s 0.95% runtime.cmpbytes
0.06s 0.29% 75.19% 0.20s 0.95% runtime.deferproc
0.20s 0.95% 76.14% 0.20s 0.95% runtime.newdefer
0.01s 0.048% 76.19% 0.19s 0.9% github.com/syndtr/goleveldb/leveldb/cache.(*Handle).Release
0.19s 0.9% 77.10% 0.19s 0.9% runtime.memclr
0.02s 0.095% 77.19% 0.18s 0.86% github.com/ethereum/go-ethereum/rlp.(*Stream).Bytes
0.18s 0.86% 78.05% 0.18s 0.86% runtime.cmpbody
0.09s 0.43% 78.48% 0.18s 0.86% runtime.growslice
0.17s 0.81% 79.29% 0.17s 0.81% encoding/binary.Uvarint
0.17s 0.81% 80.10% 0.17s 0.81% github.com/syndtr/goleveldb/leveldb.internalKey.assert
0.04s 0.19% 80.29% 0.17s 0.81% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Get
0.07s 0.33% 80.62% 0.17s 0.81% runtime.makeslice
0.17s 0.81% 81.43% 0.17s 0.81% runtime.writebarrierptr
0.06s 0.29% 81.71% 0.16s 0.76% github.com/ethereum/go-ethereum/rlp.(*Stream).readFull
0.01s 0.048% 81.76% 0.16s 0.76% github.com/ethereum/go-ethereum/rlp.(*Stream).readKind
0.02s 0.095% 81.86% 0.16s 0.76% github.com/syndtr/goleveldb/leveldb/cache.(*Node).unrefLocked
0.04s 0.19% 82.05% 0.16s 0.76% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Put
0.04s 0.19% 82.24% 0.15s 0.71% github.com/syndtr/goleveldb/leveldb/table.(*Reader).newBlockIter
0.04s 0.19% 82.43% 0.15s 0.71% runtime.nilinterhash
0.14s 0.67% 83.10% 0.14s 0.67% MCentral_Grow
0.06s 0.29% 83.38% 0.14s 0.67% runtime.mapaccess2
0.03s 0.14% 83.52% 0.14s 0.67% sync.(*Mutex).Lock
0.14s 0.67% 84.19% 0.14s 0.67% sync/atomic.AddUint32
0.02s 0.095% 84.29% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb.(*DB).acquireSnapshot
0 0% 84.29% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb.func·030
0.02s 0.095% 84.38% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb.memGet
0.07s 0.33% 84.71% 0.13s 0.62% github.com/syndtr/goleveldb/leveldb/table.(*block).entry
0.13s 0.62% 85.33% 0.13s 0.62% runtime.releasem
0 0% 85.33% 0.12s 0.57% github.com/hashicorp/golang-lru.(*Cache).Get
0 0% 85.33% 0.12s 0.57% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).delete
0.02s 0.095% 85.43% 0.12s 0.57% github.com/syndtr/goleveldb/leveldb/cache.(*mBucket).delete
0 0% 85.43% 0.12s 0.57% reflect.Value.Interface
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment