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