Griblib er et bibliotek for å parse binære filer for værdata. Disse filene inneholder komprimerte data om prediksjoner og observasjoner av meteorologiske data. I denne bloggposten vil jeg vise hvordan jeg brukte de innebygde verktøyene til Go for å nøyaktig profilere biblioteket og forbedre ytelsen til biblioteket.

Profilering av testene

I vårt tilfelle gjør vi profilering på testene til griblib. Det er ca 17 tester der som eksekverer den samme koden men som verifiserer ulike deler av resultatet.

For å kjøre testene som normalt bruker vi kommandoen go test - v. For å kjøre testene med profilering legger vi på noen flagg for cpu- og minne-profilering:

go test -memprofile memprofile.out -cpuprofile profile.out

Dette kjører testene med profilering og lagrer resultatene i filene memprofile.out og cpuprofile.out.

Vi kan inspisere disse med kommandoen go tool pprof <filnavn>. Først inspiserer vi cpu-bruken:

go tool pprof -web cpuprofile.out

Denne kommandoen åpner nettleseren din og viser en svg med detaljert info om hvordan tidsbruken fordeler seg. Dette kan være litt overveldende siden den inkluderer absolutt alle funksjoner som blir kjørt av testene. Ved å bruke kommandolinjen får vi enklere oversikt:

go tool pprof cpuprofile.out

File: gribtest.test
Type: cpu
Time: Mar 10, 2020 at 9:21pm (CET)
Duration: 5.22s, Total samples = 5.35s (102.40%)
Entering interactive mode (type "help" for commands, "o" for options)

Dette åpner pprof som gir oss mulighet til å blant annet se topp 10 tidstyver med kommandoen top10:

(pprof) top10
Showing nodes accounting for 3740ms, 69.91% of 5350ms total
Dropped 104 nodes (cum <= 26.75ms)
Showing top 10 nodes out of 89
  flat  flat%   sum%        cum   cum%
 880ms 16.45% 16.45%     1390ms 25.98%  github.com/nilsmagnus/grib/griblib.(*BitReader).readBit
 590ms 11.03% 27.48%     1980ms 37.01%  github.com/nilsmagnus/grib/griblib.(*BitReader).readUint
 530ms  9.91% 37.38%      530ms  9.91%  runtime.memmove
 470ms  8.79% 46.17%      470ms  8.79%  runtime.memclrNoHeapPointers
 290ms  5.42% 51.59%      290ms  5.42%  github.com/nilsmagnus/grib/griblib.(*BitReader).currentBit
 290ms  5.42% 57.01%     2690ms 50.28%  github.com/nilsmagnus/grib/griblib.(*BitReader).readIntsBlock
 210ms  3.93% 60.93%      500ms  9.35%  encoding/binary.(*decoder).value
 190ms  3.55% 64.49%      210ms  3.93%  bytes.(*Buffer).ReadByte
 160ms  2.99% 67.48%      690ms 12.90%  runtime.mallocgc
 130ms  2.43% 69.91%      460ms  8.60%  github.com/nilsmagnus/grib/griblib.(*Data2).scaleValues

Hvis vi vil kan vi ytterligere inspisere de ulike funksjonene med list <navn-på-funksjon>:

 (pprof) list readBit
 
 Total: 5.35s
 ROUTINE ======================== github.com/nilsmagnus/grib/griblib.(*BitReader).readBit in /home/larsgard/go/src/github.com/nilsmagnus/grib/griblib/bitreader.go
 880ms      1.39s (flat, cum) 25.98% of Total
     .          .     31:	dataReader.Read(rawData)
     .          .     32:	buffer := bytes.NewBuffer(rawData)
     .          .     33:	return newReader(buffer)
     .          .     34:}
     .          .     35:
 220ms      220ms     36:func (r *BitReader) readBit() (uint, error) {
 140ms      140ms     37:	if r.offset == 8 {
  50ms       60ms     38:		r.resetOffset()
     .          .     39:	}
 160ms      160ms     40:	if r.offset == 0 {
     .          .     41:		var err error
  50ms      260ms     42:		if r.byte, err = r.reader.ReadByte(); err != nil {
     .          .     43:			return 0, err
     .          .     44:		}
     .          .     45:	}
  20ms      310ms     46:	bit := uint(r.currentBit())
  10ms       10ms     47:	r.offset++
 230ms      230ms     48:	return bit, nil
     .          .     49:}
     .          .     50:
     .          .     51:func (r *BitReader) readUint(nbits int) (uint64, error) {
     .          .     52:	var result uint64
     .          .     53:	for i := nbits - 1; i >= 0; i-- {

Mye tidsbruk på minnehåndtering

Naturlig nok er det mange funksjoner fra biblioteket vårt som ligger på topp, men det er bekymringsverdig at funksjoner som memmove og memclrNoHeapPointers dukker opp. Dette betyr at mye av tiden går med til garbage-collection og minnehåndtering, noe som er rart med en så effektiv garbage-collector som følger med i Go-runtimen.

Vi inspiserer derfor minnebruken på samme måte for å finne topp 10 minnetyver:

go tool pprof memprofile.out
(pprof) top10
Showing nodes accounting for 8.32GB, 99.82% of 8.33GB total
Dropped 29 nodes (cum <= 0.04GB)
Showing top 10 nodes out of 22
  flat  flat%   sum%        cum   cum%
4.39GB 52.72% 52.72%     5.48GB 65.74%  github.com/nilsmagnus/grib/griblib.(*Data2).extractData
2.13GB 25.61% 78.33%     2.13GB 25.61%  github.com/nilsmagnus/grib/griblib.(*Data2).scaleValues
0.97GB 11.63% 89.96%     0.97GB 11.63%  github.com/nilsmagnus/grib/griblib.(*BitReader).readIntsBlock
0.25GB  3.04% 93.00%     0.50GB  5.96%  github.com/nilsmagnus/grib/griblib.(*Data2).extractBitGroupParameters
0.25GB  2.99% 95.99%     0.25GB  2.99%  github.com/nilsmagnus/grib/griblib.(*BitReader).readUintsBlock
0.12GB  1.39% 97.38%     0.12GB  1.39%  github.com/nilsmagnus/grib/griblib.bitGroupParameter.zeroGroup
0.05GB  0.65% 98.02%     8.27GB 99.25%  github.com/nilsmagnus/grib/griblib.readMessage
0.05GB  0.63% 98.66%     8.32GB 99.89%  github.com/nilsmagnus/grib/griblib.ReadMessage
0.05GB  0.59% 99.25%     0.05GB  0.59%  github.com/nilsmagnus/grib/griblib.makeBitReader
0.05GB  0.57% 99.82%     0.05GB  0.57%  encoding/binary.Read

Den verste funksjonen allokerer 4.39GB minne under testene!! Ved bruk av list <navn-på-funksjon> finner vi syndebukken med kirurgisk presisjon:

(pprof) list extractData
Total: 8.33GB
ROUTINE ======================== github.com/nilsmagnus/grib/griblib.(*Data2).extractData in /home/larsgard/go/src/github.com/nilsmagnus/grib/griblib/data2.go
4.39GB     5.48GB (flat, cum) 65.74% of Total
     .          .    105:func (template *Data2) extractData(bitReader *BitReader, bitGroups []bitGroupParameter) ([]int64, []int64, error) {
     .          .    106:	section7Data := []int64{}
     .          .    107:	ifldmiss := []int64{}
     .          .    108:
     .          .    109:	for _, bitGroup := range bitGroups {
     .     1.08GB    110:		tmp, err := bitGroup.readData(bitReader)
     .          .    111:		if err != nil {
     .          .    112:			return section7Data, ifldmiss, fmt.Errorf("bitGroup read: %s", err.Error())
     .          .    113:		}
     .          .    114:		switch template.MissingValue {
     .          .    115:		case 0:
     .          .    116:			for _, elt := range tmp {
2.10GB     2.10GB    117:				section7Data = append(section7Data, elt+int64(bitGroup.Reference))
2.12GB     2.12GB    118:				ifldmiss = append(ifldmiss, 0)
     .          .    119:			}
....

Det er altså 2 kodelinjer(linje 117 og 118) som står for 4GB av minnebruken og begge bruker den innebygde funksjonen append.

Append legger til et element i en slice. Men hvis det ikke er nok kapasitet i den underliggende arrayen til slicen så blir det opprettet en ny slice med dobbel kapasitet for å sikre «amortisert lineær kompleksitet» (1). Dvs at dette er en god måte å håndeter for liten kapasitet i en slice i de fleste tilfeller. For oss er det en katastrofe fordi vi opererer på ganske store slicer som blir utvidet mange ganger og fører til mye arbeid for GC.

Endringer i koden

Endringene i koden blir som følger: istedenfor å opprette en tom slice for å appende på den, så oppretter vi en slice med preallokert størrelse siden vi egentlig vet hvor stor slicen skal bli. I tillegg må vi manuelt håndtere indekser når vi allokerer verdier til slicene. Altså, istedenfor

minSlice := []int64{} // opprette slice med 0 i kapasitet
minSlice = append(minSlice, nyverdi) // bruke append for å legge til en verdi i slutten av slicen

så blir det

size := calculateSizeSomehow()
minSlice := make([]int64,size)
minSlice[indeks] = nyverdi
indeks++

Vi ofrer altså lesbarhet for ytelse. De første testene etter å ha gjort dette viste forbedringer.

Ytelsesforbedringer!

Så, etter en del optimaliseringer kjører vi testene på nytt og ser at tidsbruken har gått fra 5.4 sekunder til ca 3.5 sekunder. Og vi bruker ikke så mye tid på GC lenger:

22:24 $ go tool pprof cpuprofile.out 
File: gribtest.test
Type: cpu
Time: Mar 10, 2020 at 10:24pm (CET)
Duration: 3.76s, Total samples = 3.59s (95.36%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 2980ms, 83.01% of 3590ms total
Dropped 60 nodes (cum <= 17.95ms)
Showing top 10 nodes out of 66
  flat  flat%   sum%        cum   cum%
1190ms 33.15% 33.15%     1320ms 36.77%  github.com/nilsmagnus/grib/griblib.(*BitReader).readBit
 760ms 21.17% 54.32%     2080ms 57.94%  github.com/nilsmagnus/grib/griblib.(*BitReader).readUint
 230ms  6.41% 60.72%      230ms  6.41%  runtime.memclrNoHeapPointers
 140ms  3.90% 64.62%     1950ms 54.32%  github.com/nilsmagnus/grib/griblib.(*BitReader).readIntsBlock
 130ms  3.62% 68.25%      500ms 13.93%  encoding/binary.(*decoder).value
 120ms  3.34% 71.59%      190ms  5.29%  reflect.Value.Index
 110ms  3.06% 74.65%     2250ms 62.67%  github.com/nilsmagnus/grib/griblib.(*Data2).extractData
 100ms  2.79% 77.44%      130ms  3.62%  bytes.(*Buffer).ReadByte
 100ms  2.79% 80.22%      200ms  5.57%  github.com/nilsmagnus/grib/griblib.(*Data2).scaleValues
 100ms  2.79% 83.01%      100ms  2.79%  github.com/nilsmagnus/grib/griblib.(*Data3).applySpacialDifferencing

Vi ser at funksjonen memclrNoHeapPointers forstatt bruker en del cpu, så det er sikkert flere steder koden kan optimaliseres.

Minneforbruket har også gått ned fra 8.33GB til 2.2GB :

22:25 $ go tool pprof memprofile.out 
File: gribtest.test
Type: alloc_space
Time: Mar 10, 2020 at 10:24pm (CET)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 2152.67MB, 99.30% of 2167.80MB total
Dropped 33 nodes (cum <= 10.84MB)
Showing top 10 nodes out of 22
  flat  flat%   sum%        cum   cum%
801.65MB 36.98% 36.98%  1220.81MB 56.32%  github.com/nilsmagnus/grib/griblib.(*Data2).extractData
420.50MB 19.40% 56.38%   420.50MB 19.40%  github.com/nilsmagnus/grib/griblib.(*Data2).scaleValues
374.09MB 17.26% 73.63%   374.09MB 17.26%  github.com/nilsmagnus/grib/griblib.(*BitReader).readIntsBlock
233.18MB 10.76% 84.39%   305.45MB 14.09%  github.com/nilsmagnus/grib/griblib.(*Data2).extractBitGroupParameters
72.27MB  3.33% 87.72%    72.27MB  3.33%  github.com/nilsmagnus/grib/griblib.(*BitReader).readUintsBlock
55.79MB  2.57% 90.30%    55.79MB  2.57%  encoding/binary.Read
54.67MB  2.52% 92.82%  2156.54MB 99.48%  github.com/nilsmagnus/grib/griblib.ReadMessage
47.80MB  2.21% 95.03%  2101.87MB 96.96%  github.com/nilsmagnus/grib/griblib.readMessage
47.64MB  2.20% 97.22%    47.64MB  2.20%  github.com/nilsmagnus/grib/griblib.makeBitReader
45.07MB  2.08% 99.30%    45.07MB  2.08%  github.com/nilsmagnus/grib/griblib.(*bitGroupParameter).zeroGroup (inline)

Go tooling rocker

Go er et enkelt programmeringsspråk med enkle verktøy. Med profileringsverktøyene som er innebygd i Go er det lett å pinpointe akkurat hvor vi kan optimalisere koden uten å måtte ty til komplekse analyseprogram og 3.parts verktøy. Det enkle er ofte det beste :)

(Hvis du vil kjøre testene selv, så kan du sjekke ut koden fra github og git-taggen before-optimize for å kjøre testene før koden ble optimialisert og master/HEAD for å kjøre testene etter optimaliseringen.)

(1) Donovan and Kernighan, «The Go Programming Language», Kap. 4.2.1.