Skip to content

Instantly share code, notes, and snippets.

@zsfelfoldi

zsfelfoldi/prof_new

Created April 10, 2016 17:37
Show Gist options
  • Save zsfelfoldi/7e33c333d7c180b44b25dfb20a84db9f to your computer and use it in GitHub Desktop.
Save zsfelfoldi/7e33c333d7c180b44b25dfb20a84db9f to your computer and use it in GitHub Desktop.
Download ZIP
Raw
prof_new
Benchmarking 100000 consecutive header reads from an existing "new style" database (found at DefaultDataDir/_new):
(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_new_header_100k -run XXX -cpuprofile new.prof
PASS
BenchmarkReadChain_new_header_100k-2 1 6754975060 ns/op
ok _/home/fefe/go-ethereum/core 7.218s
CPU profile top 100 nodes (both flat and cumulative are listed):
fefe@Fefe-ThinkPad-SL500:~/go-ethereum$ go tool pprof core.test.new new.prof
Entering interactive mode (type "help" for commands)
(pprof) top 100
4.85s of 5.61s total (86.45%)
Dropped 107 nodes (cum <= 0.03s)
Showing top 100 nodes out of 155 (cum >= 0.07s)
flat flat% sum% cum cum%
0.28s 4.99% 4.99% 0.33s 5.88% runtime.mallocgc
0.25s 4.46% 9.45% 0.25s 4.46% runtime.memmove
0.18s 3.21% 12.66% 0.31s 5.53% runtime.deferreturn
0.17s 3.03% 15.69% 0.23s 4.10% github.com/golang/snappy.Decode
0.17s 3.03% 18.72% 0.17s 3.03% runtime.memclr
0.13s 2.32% 21.03% 0.13s 2.32% runtime.cmpbody
0.12s 2.14% 23.17% 0.12s 2.14% MCentral_Grow
0.12s 2.14% 25.31% 0.12s 2.14% sync/atomic.AddUint32
0.11s 1.96% 27.27% 0.11s 1.96% runtime.newdefer
0.11s 1.96% 29.23% 0.76s 13.55% sort.Search
0.10s 1.78% 31.02% 0.37s 6.60% github.com/syndtr/goleveldb/leveldb.func·028
0.10s 1.78% 32.80% 0.19s 3.39% github.com/syndtr/goleveldb/leveldb.internalKey.ukey
0.10s 1.78% 34.58% 0.10s 1.78% runtime.MSpan_Sweep
0.10s 1.78% 36.36% 0.10s 1.78% runtime.writebarrierptr
0.09s 1.60% 37.97% 0.61s 10.87% github.com/syndtr/goleveldb/leveldb.(*iComparer).Compare
0.09s 1.60% 39.57% 0.09s 1.60% github.com/syndtr/goleveldb/leveldb.internalKey.assert
0.09s 1.60% 41.18% 0.28s 4.99% github.com/syndtr/goleveldb/leveldb/table.func·001
0.08s 1.43% 42.60% 0.26s 4.63% github.com/syndtr/goleveldb/leveldb/comparer.bytesComparer.Compare
0.08s 1.43% 44.03% 0.08s 1.43% runtime.releasem
0.07s 1.25% 45.28% 0.07s 1.25% encoding/binary.Uvarint
0.07s 1.25% 46.52% 0.33s 5.88% github.com/syndtr/goleveldb/leveldb/comparer.(*bytesComparer).Compare
0.07s 1.25% 47.77% 0.10s 1.78% github.com/syndtr/goleveldb/leveldb/table.(*block).entry
0.07s 1.25% 49.02% 0.07s 1.25% hash/crc32.update
0.07s 1.25% 50.27% 0.07s 1.25% runtime.memhash
0.06s 1.07% 51.34% 0.73s 13.01% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Seek
0.06s 1.07% 52.41% 0.12s 2.14% runtime.deferproc
0.06s 1.07% 53.48% 0.10s 1.78% runtime.freedefer
0.06s 1.07% 54.55% 0.12s 2.14% runtime.makeslice
0.06s 1.07% 55.61% 0.29s 5.17% runtime.newobject
0.06s 1.07% 56.68% 0.06s 1.07% scanblock
0.05s 0.89% 57.58% 0.18s 3.21% runtime.cmpbytes
0.05s 0.89% 58.47% 0.16s 2.85% runtime.growslice
0.05s 0.89% 59.36% 0.05s 0.89% runtime.unlock
0.04s 0.71% 60.07% 0.04s 0.71% ExternalCode
0.04s 0.71% 60.78% 0.13s 2.32% github.com/ethereum/go-ethereum/rlp.(*Stream).Bytes
0.04s 0.71% 61.50% 0.04s 0.71% github.com/ethereum/go-ethereum/rlp.(*Stream).willRead
0.04s 0.71% 62.21% 2.66s 47.42% github.com/syndtr/goleveldb/leveldb.(*version).walkOverlapping
0.04s 0.71% 62.92% 0.05s 0.89% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).getBucket
0.04s 0.71% 63.64% 1.84s 32.80% github.com/syndtr/goleveldb/leveldb/table.(*Reader).find
0.04s 0.71% 64.35% 0.67s 11.94% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getDataIter
0.04s 0.71% 65.06% 0.77s 13.73% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlockCached
0.04s 0.71% 65.78% 0.04s 0.71% reflect.packEface
0.04s 0.71% 66.49% 0.04s 0.71% runtime.deferproc_m
0.04s 0.71% 67.20% 0.10s 1.78% runtime.nilinterhash
0.04s 0.71% 67.91% 0.08s 1.43% sync.(*Mutex).Lock
0.04s 0.71% 68.63% 0.04s 0.71% sync/atomic.CompareAndSwapUint32
0.03s 0.53% 69.16% 0.06s 1.07% bytes.(*Reader).Read
0.03s 0.53% 69.70% 0.03s 0.53% encoding/binary.littleEndian.Uint64
0.03s 0.53% 70.23% 0.85s 15.15% github.com/ethereum/go-ethereum/rlp.(*Stream).Decode
0.03s 0.53% 70.77% 0.16s 2.85% github.com/ethereum/go-ethereum/rlp.(*Stream).Kind
0.03s 0.53% 71.30% 0.10s 1.78% github.com/ethereum/go-ethereum/rlp.(*Stream).readFull
0.03s 0.53% 71.84% 0.23s 4.10% github.com/ethereum/go-ethereum/rlp.decodeByteArray
0.03s 0.53% 72.37% 2.96s 52.76% github.com/syndtr/goleveldb/leveldb.(*DB).get
0.03s 0.53% 72.91% 0.10s 1.78% github.com/syndtr/goleveldb/leveldb/table.(*Reader).newBlockIter
0.03s 0.53% 73.44% 0.08s 1.43% math/big.nat.setBytes
0.03s 0.53% 73.98% 0.04s 0.71% runtime.assertI2T2
0.03s 0.53% 74.51% 0.05s 0.89% runtime.mapassign1
0.03s 0.53% 75.04% 0.06s 1.07% sync.(*RWMutex).RLock
0.03s 0.53% 75.58% 0.03s 0.53% syscall.Syscall6
0.02s 0.36% 75.94% 0.05s 0.89% container/list.(*List).insertValue
0.02s 0.36% 76.29% 3.18s 56.68% github.com/ethereum/go-ethereum/ethdb.(*LDBDatabase).Get
0.02s 0.36% 76.65% 0.08s 1.43% github.com/ethereum/go-ethereum/rlp.(*Stream).List
0.02s 0.36% 77.01% 0.07s 1.25% github.com/ethereum/go-ethereum/rlp.(*Stream).readByte
0.02s 0.36% 77.36% 0.13s 2.32% github.com/ethereum/go-ethereum/rlp.(*Stream).readKind
0.02s 0.36% 77.72% 0.96s 17.11% github.com/ethereum/go-ethereum/rlp.Decode
0.02s 0.36% 78.07% 0.69s 12.30% github.com/ethereum/go-ethereum/rlp.func·005
0.02s 0.36% 78.43% 0.09s 1.60% github.com/syndtr/goleveldb/leveldb.(*DB).getMems
0.02s 0.36% 78.79% 0.06s 1.07% github.com/syndtr/goleveldb/leveldb.(*DB).releaseSnapshot
0.02s 0.36% 79.14% 2.08s 37.08% github.com/syndtr/goleveldb/leveldb.(*tOps).find
0.02s 0.36% 79.50% 2.68s 47.77% github.com/syndtr/goleveldb/leveldb.(*version).get
0.02s 0.36% 79.86% 0.04s 0.71% github.com/syndtr/goleveldb/leveldb.internalKey.num
0.02s 0.36% 80.21% 0.82s 14.62% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Get
0.02s 0.36% 80.57% 0.05s 0.89% github.com/syndtr/goleveldb/leveldb/memdb.(*DB).findGE
0.02s 0.36% 80.93% 1.86s 33.16% github.com/syndtr/goleveldb/leveldb/table.(*Reader).Find
0.02s 0.36% 81.28% 0.20s 3.57% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Next
0.02s 0.36% 81.64% 0.03s 0.53% github.com/syndtr/goleveldb/leveldb/table.decodeBlockHandle
0.02s 0.36% 82.00% 0.04s 0.71% runtime.mapaccess1
0.02s 0.36% 82.35% 0.06s 1.07% sync.(*Mutex).Unlock
0.02s 0.36% 82.71% 0.06s 1.07% sync.(*RWMutex).RUnlock
0.01s 0.18% 82.89% 2.83s 50.45% _/home/fefe/go-ethereum/core.(*HeaderChain).getHeader
0.01s 0.18% 83.07% 1.75s 31.19% _/home/fefe/go-ethereum/core.GetCanonicalHash
0.01s 0.18% 83.24% 2.55s 45.45% _/home/fefe/go-ethereum/core.GetHeader
0.01s 0.18% 83.42% 1.55s 27.63% _/home/fefe/go-ethereum/core.GetHeaderRLP
0.01s 0.18% 83.60% 0.09s 1.60% github.com/ethereum/go-ethereum/rlp.(*Stream).Reset
0.01s 0.18% 83.78% 3.16s 56.33% github.com/syndtr/goleveldb/leveldb.(*DB).Get
0.01s 0.18% 83.96% 0.03s 0.53% github.com/syndtr/goleveldb/leveldb.(*iComparer).uCompare
0.01s 0.18% 84.14% 2.12s 37.79% github.com/syndtr/goleveldb/leveldb.func·032
0.01s 0.18% 84.31% 0.03s 0.53% github.com/syndtr/goleveldb/leveldb.makeInternalKey
0.01s 0.18% 84.49% 0.04s 0.71% github.com/syndtr/goleveldb/leveldb/cache.(*Handle).Release
0.01s 0.18% 84.67% 0.08s 1.43% github.com/syndtr/goleveldb/leveldb/cache.(*lru).Promote
0.01s 0.18% 84.85% 0.04s 0.71% github.com/syndtr/goleveldb/leveldb/cache.(*mBucket).get
0.01s 0.18% 85.03% 0.06s 1.07% github.com/syndtr/goleveldb/leveldb/memdb.(*DB).Find
0.01s 0.18% 85.20% 0.03s 0.53% github.com/syndtr/goleveldb/leveldb/storage.fsParseName
0.01s 0.18% 85.38% 0.32s 5.70% github.com/syndtr/goleveldb/leveldb/table.(*block).seek
0.01s 0.18% 85.56% 0.04s 0.71% github.com/syndtr/goleveldb/leveldb/util.(*BufferPool).Get
0.01s 0.18% 85.74% 0.09s 1.60% math/big.(*Int).SetBytes
0.01s 0.18% 85.92% 0.06s 1.07% reflect.Value.Interface
0.01s 0.18% 86.10% 0.05s 0.89% reflect.valueInterface
0.01s 0.18% 86.27% 0.06s 1.07% runtime.mapaccess2
0.01s 0.18% 86.45% 0.07s 1.25% runtime.mapdelete
(pprof)
(pprof)
(pprof)
(pprof) top 100 -cum
4.11s of 5.61s total (73.26%)
Dropped 107 nodes (cum <= 0.03s)
Showing top 100 nodes out of 155 (cum >= 0.06s)
flat flat% sum% cum cum%
0 0% 0% 4.68s 83.42% runtime.goexit
0 0% 0% 4.64s 82.71% _/home/fefe/go-ethereum/core.BenchmarkReadChain_new_header_100k
0 0% 0% 4.64s 82.71% _/home/fefe/go-ethereum/core.benchReadChain
0 0% 0% 4.64s 82.71% testing.(*B).launch
0 0% 0% 4.64s 82.71% testing.(*B).runN
0 0% 0% 4.58s 81.64% _/home/fefe/go-ethereum/core.(*BlockChain).GetHeaderByNumber
0 0% 0% 4.58s 81.64% _/home/fefe/go-ethereum/core.(*HeaderChain).GetHeaderByNumber
0.02s 0.36% 0.36% 3.18s 56.68% github.com/ethereum/go-ethereum/ethdb.(*LDBDatabase).Get
0.01s 0.18% 0.53% 3.16s 56.33% github.com/syndtr/goleveldb/leveldb.(*DB).Get
0.03s 0.53% 1.07% 2.96s 52.76% github.com/syndtr/goleveldb/leveldb.(*DB).get
0.01s 0.18% 1.25% 2.83s 50.45% _/home/fefe/go-ethereum/core.(*HeaderChain).getHeader
0.02s 0.36% 1.60% 2.68s 47.77% github.com/syndtr/goleveldb/leveldb.(*version).get
0.04s 0.71% 2.32% 2.66s 47.42% github.com/syndtr/goleveldb/leveldb.(*version).walkOverlapping
0.01s 0.18% 2.50% 2.55s 45.45% _/home/fefe/go-ethereum/core.GetHeader
0.01s 0.18% 2.67% 2.12s 37.79% github.com/syndtr/goleveldb/leveldb.func·032
0.02s 0.36% 3.03% 2.08s 37.08% github.com/syndtr/goleveldb/leveldb.(*tOps).find
0.02s 0.36% 3.39% 1.86s 33.16% github.com/syndtr/goleveldb/leveldb/table.(*Reader).Find
0.04s 0.71% 4.10% 1.84s 32.80% github.com/syndtr/goleveldb/leveldb/table.(*Reader).find
0.01s 0.18% 4.28% 1.75s 31.19% _/home/fefe/go-ethereum/core.GetCanonicalHash
0.01s 0.18% 4.46% 1.55s 27.63% _/home/fefe/go-ethereum/core.GetHeaderRLP
0.02s 0.36% 4.81% 0.96s 17.11% github.com/ethereum/go-ethereum/rlp.Decode
0 0% 4.81% 0.86s 15.33% System
0.03s 0.53% 5.35% 0.85s 15.15% github.com/ethereum/go-ethereum/rlp.(*Stream).Decode
0.02s 0.36% 5.70% 0.82s 14.62% github.com/syndtr/goleveldb/leveldb/cache.(*Cache).Get
0.04s 0.71% 6.42% 0.77s 13.73% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlockCached
0.11s 1.96% 8.38% 0.76s 13.55% sort.Search
0.06s 1.07% 9.45% 0.73s 13.01% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Seek
0.02s 0.36% 9.80% 0.69s 12.30% github.com/ethereum/go-ethereum/rlp.func·005
0 0% 9.80% 0.69s 12.30% github.com/syndtr/goleveldb/leveldb/cache.(*NamespaceGetter).Get
0.04s 0.71% 10.52% 0.67s 11.94% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getDataIter
0.09s 1.60% 12.12% 0.61s 10.87% github.com/syndtr/goleveldb/leveldb.(*iComparer).Compare
0 0% 12.12% 0.45s 8.02% github.com/syndtr/goleveldb/leveldb.tFiles.searchMax
0.10s 1.78% 13.90% 0.37s 6.60% github.com/syndtr/goleveldb/leveldb.func·028
0 0% 13.90% 0.37s 6.60% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readBlock
0 0% 13.90% 0.37s 6.60% github.com/syndtr/goleveldb/leveldb/table.(*Reader).readRawBlock
0 0% 13.90% 0.35s 6.24% github.com/syndtr/goleveldb/leveldb/table.func·003
0 0% 13.90% 0.33s 5.88% github.com/ethereum/go-ethereum/rlp.decodeBigInt
0.07s 1.25% 15.15% 0.33s 5.88% github.com/syndtr/goleveldb/leveldb/comparer.(*bytesComparer).Compare
0.28s 4.99% 20.14% 0.33s 5.88% runtime.mallocgc
0.01s 0.18% 20.32% 0.32s 5.70% github.com/syndtr/goleveldb/leveldb/table.(*block).seek
0.18s 3.21% 23.53% 0.31s 5.53% runtime.deferreturn
0.06s 1.07% 24.60% 0.29s 5.17% runtime.newobject
0.09s 1.60% 26.20% 0.28s 4.99% github.com/syndtr/goleveldb/leveldb/table.func·001
0.08s 1.43% 27.63% 0.26s 4.63% github.com/syndtr/goleveldb/leveldb/comparer.bytesComparer.Compare
0.25s 4.46% 32.09% 0.25s 4.46% runtime.memmove
0.03s 0.53% 32.62% 0.23s 4.10% github.com/ethereum/go-ethereum/rlp.decodeByteArray
0.17s 3.03% 35.65% 0.23s 4.10% github.com/golang/snappy.Decode
0.02s 0.36% 36.01% 0.20s 3.57% github.com/syndtr/goleveldb/leveldb/table.(*blockIter).Next
0 0% 36.01% 0.19s 3.39% github.com/hashicorp/golang-lru.(*Cache).Add
0.10s 1.78% 37.79% 0.19s 3.39% github.com/syndtr/goleveldb/leveldb.internalKey.ukey
0.05s 0.89% 38.68% 0.18s 3.21% runtime.cmpbytes
0 0% 38.68% 0.17s 3.03% github.com/hashicorp/golang-lru/simplelru.(*LRU).Add
0.17s 3.03% 41.71% 0.17s 3.03% runtime.memclr
0.03s 0.53% 42.25% 0.16s 2.85% github.com/ethereum/go-ethereum/rlp.(*Stream).Kind
0 0% 42.25% 0.16s 2.85% github.com/syndtr/goleveldb/leveldb/table.(*Reader).getIndexBlock
0.05s 0.89% 43.14% 0.16s 2.85% runtime.growslice
0.04s 0.71% 43.85% 0.13s 2.32% github.com/ethereum/go-ethereum/rlp.(*Stream).Bytes
0.02s 0.36% 44.21% 0.13s 2.32% github.com/ethereum/go-ethereum/rlp.(*Stream).readKind
0 0% 44.21% 0.13s 2.32% github.com/syndtr/goleveldb/leveldb.(*tOps).open
0.13s 2.32% 46.52% 0.13s 2.32% runtime.cmpbody
0.12s 2.14% 48.66% 0.12s 2.14% MCentral_Grow
0.06s 1.07% 49.73% 0.12s 2.14% runtime.deferproc
0.06s 1.07% 50.80% 0.12s 2.14% runtime.makeslice
0.12s 2.14% 52.94% 0.12s 2.14% sync/atomic.AddUint32
0.11s 1.96% 54.90% 0.11s 1.96% runtime.newdefer
0.03s 0.53% 55.44% 0.10s 1.78% github.com/ethereum/go-ethereum/rlp.(*Stream).readFull
0.03s 0.53% 55.97% 0.10s 1.78% github.com/syndtr/goleveldb/leveldb/table.(*Reader).newBlockIter
0.07s 1.25% 57.22% 0.10s 1.78% github.com/syndtr/goleveldb/leveldb/table.(*block).entry
0.10s 1.78% 59.00% 0.10s 1.78% runtime.MSpan_Sweep
0.06s 1.07% 60.07% 0.10s 1.78% runtime.freedefer
0.04s 0.71% 60.78% 0.10s 1.78% runtime.nilinterhash
0.10s 1.78% 62.57% 0.10s 1.78% runtime.writebarrierptr
0.01s 0.18% 62.75% 0.09s 1.60% github.com/ethereum/go-ethereum/rlp.(*Stream).Reset
0 0% 62.75% 0.09s 1.60% github.com/ethereum/go-ethereum/rlp.NewStream
0.02s 0.36% 63.10% 0.09s 1.60% github.com/syndtr/goleveldb/leveldb.(*DB).getMems
0.09s 1.60% 64.71% 0.09s 1.60% github.com/syndtr/goleveldb/leveldb.internalKey.assert
0.01s 0.18% 64.88% 0.09s 1.60% math/big.(*Int).SetBytes
0.02s 0.36% 65.24% 0.08s 1.43% github.com/ethereum/go-ethereum/rlp.(*Stream).List
0 0% 65.24% 0.08s 1.43% github.com/hashicorp/golang-lru.(*Cache).Get
0.01s 0.18% 65.42% 0.08s 1.43% github.com/syndtr/goleveldb/leveldb/cache.(*lru).Promote
0.03s 0.53% 65.95% 0.08s 1.43% math/big.nat.setBytes
0.08s 1.43% 67.38% 0.08s 1.43% runtime.releasem
0.04s 0.71% 68.09% 0.08s 1.43% sync.(*Mutex).Lock
0 0% 68.09% 0.07s 1.25% GC
0.07s 1.25% 69.34% 0.07s 1.25% encoding/binary.Uvarint
0.02s 0.36% 69.70% 0.07s 1.25% github.com/ethereum/go-ethereum/rlp.(*Stream).readByte
0 0% 69.70% 0.07s 1.25% github.com/hashicorp/golang-lru/simplelru.(*LRU).removeElement
0 0% 69.70% 0.07s 1.25% github.com/hashicorp/golang-lru/simplelru.(*LRU).removeOldest
0 0% 69.70% 0.07s 1.25% github.com/syndtr/goleveldb/leveldb/util.CRC.Update
0 0% 69.70% 0.07s 1.25% github.com/syndtr/goleveldb/leveldb/util.NewCRC
0 0% 69.70% 0.07s 1.25% hash/crc32.Update
0.07s 1.25% 70.94% 0.07s 1.25% hash/crc32.update
0 0% 70.94% 0.07s 1.25% hash/crc32.updateCastagnoli
0.01s 0.18% 71.12% 0.07s 1.25% runtime.mapdelete
0.07s 1.25% 72.37% 0.07s 1.25% runtime.memhash
0.03s 0.53% 72.91% 0.06s 1.07% bytes.(*Reader).Read
0 0% 72.91% 0.06s 1.07% github.com/ethereum/go-ethereum/ethdb.NewLDBDatabase
0 0% 72.91% 0.06s 1.07% github.com/ethereum/go-ethereum/rlp.cachedTypeInfo
0 0% 72.91% 0.06s 1.07% github.com/syndtr/goleveldb/leveldb.(*DB).acquireSnapshot
0.02s 0.36% 73.26% 0.06s 1.07% github.com/syndtr/goleveldb/leveldb.(*DB).releaseSnapshot
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment