For 10 år siden stod Google over for en kritisk flaskehals, der skyldtes ekstremt lange C++-kompileringstider, og havde brug for en helt ny måde at løse problemet på. Googles ingeniører tog udfordringen op ved at skabe et nyt sprog kaldet Go (alias Golang). Det nye sprog Go låner de bedste dele af C++ (især dets ydeevne og sikkerhedsfunktioner) og kombinerer det med hastigheden i Python, så Go hurtigt kan bruge flere kerner og samtidig implementere samtidighed.

Her hos Coralogix analyserer vi vores kunders logs for at give dem indsigt i realtid, advarsler og metadata om deres logs. For at kunne gøre det, skal parsing-fasen, som er meget kompleks og fyldt med tonsvis af regler for hver loglinjetjeneste, være ekstremt hurtig. Det er en af grundene til, at vi besluttede at bruge Go lang.

Den nye tjeneste kører nu på fuld tid i produktion, og selv om vi ser gode resultater, skal den køre på højtydende maskiner. Over ti milliarder logfiler analyseres hver dag af denne Go-tjeneste, der kører på en AWS m4.2xlarge-instans med 8 CPU’er og 36 GB hukommelse.

På dette tidspunkt kunne vi have kaldt det en dag med en god fornemmelse af, at alt kører godt, men sådan kører vi ikke her hos Coralogix. Vi ville have flere funktioner (ydeevne osv.) ved hjælp af mindre (AWS-instanser). For at kunne forbedre os var vi først nødt til at forstå arten af vores flaskehalse, og hvordan vi kan reducere eller helt fjerne dem.

Vi besluttede at køre noget Golang-profilering på vores tjeneste og kontrollere, hvad der præcist forårsagede et højt CPU-forbrug for at se, om vi kan optimere.

Først har vi opgraderet til den seneste stabile Go-version (en vigtig del af softwarens livscyklus). Vi var på Go-version v1.12.4, og den seneste var 1.13.8. 1.13-udgaven havde ifølge dokumentationen store forbedringer i runtime-biblioteket og et par andre komponenter, som primært udnyttede hukommelsesforbruget. Bottom line, at arbejde med den seneste stabile version var nyttigt og sparede os for en del arbejde →

Dermed blev hukommelsesforbruget forbedret fra ca. ~800 MB til ~180 MB.

For det andet begyndte vi at profilere for at få en bedre forståelse af vores proces og forstå, hvor vi bruger tid og ressourcer.

Profilering af forskellige tjenester og programmeringssprog kan virke kompleks og intimiderende, men det er faktisk ret nemt i Go og kan beskrives med få kommandoer. Go har et dedikeret værktøj kaldet ‘pprof’, der skal aktiveres i din app ved at lytte til en rute (standardport- 6060) og bruge Go-pakken til håndtering af http-forbindelser:

import _ "net/http/pprof"

Derpå initialiseres følgende i din hovedfunktion eller under din rutepakke:

go func() {log.Println(http.ListenAndServe("localhost:6060", nil))}()

Nu kan du starte din tjeneste og oprette forbindelse til

http://localhost:6060/debug/pprof

Den fulde dokumentation af Go kan findes her.

Den standardprofilering for pprof vil være en 30 sekunders prøveudtagning af CPU-forbrug. Der er et par forskellige stier, der aktiverer prøvetagning for CPU-brug, heap-brug og mere.

Vi fokuserede på vores CPU-forbrug, så vi tog en 30 sekunders profilering i produktionen og opdagede det, du ser på billedet nedenfor (husk: dette er efter opgradering af vores Go-version og nedsættelse af de interne dele af Go til et minimum):

Go profilering – Coralogix

Som du kan se, fandt vi masser af runtime pakkeaktivitet, hvilket indikerede specifikt GC-aktivitet → Næsten 29 % af vores CPU (bare de 20 mest forbrugte objekter) bruges af GC. Da Go GC er ret hurtig og temmelig optimeret, er den bedste praksis ikke at ændre eller modificere den, og da vores hukommelsesforbrug var meget lavt (sammenlignet med vores tidligere Go-version), var den vigtigste mistanke en høj objektallokeringshastighed.

Hvis det er tilfældet, er der to ting, vi kan gøre:

  • Tune Go GC-aktivitet til at tilpasse sig vores serviceadfærd, hvilket betyder – forsinkelse af dens udløsning for at aktivere GC mindre hyppigt. Dette vil tvinge os til at kompensere med mere hukommelse.
  • Find den funktion, det område eller den linje i vores kode, der allokerer for mange objekter.

Ved at se på vores instanstype var det tydeligt, at vi havde meget hukommelse til overs, og at vi i øjeblikket er bundet af maskinens CPU. Så vi skiftede bare det forhold. Golang har siden sine tidlige dage haft et flag, som de fleste udviklere ikke er opmærksomme på, kaldet GOGC. Dette flag, med en standardværdi på 100, fortæller simpelthen systemet, hvornår GC skal udløses. Standardindstillingen vil udløse GC-processen, når heap’en når 100 % af sin oprindelige størrelse. Hvis du ændrer denne værdi til et højere tal, vil GC-udløsningen blive forsinket, og hvis du sænker den, vil GC-udløsningen blive udløst tidligere. Vi begyndte at benchmarke et par forskellige værdier, og den bedste ydelse til vores formål blev opnået ved at bruge: GOGC=2000.

Dette øgede straks vores hukommelsesforbrug fra ~200 MB til ~2,7 GB (det er efter at hukommelsesforbruget faldt som følge af vores opdatering af Go-versionen) og reducerede vores CPU-forbrug med ~10 %.
Det følgende skærmbillede viser benchmark-resultaterne:

GOGC =2000 resultater – Coralogix benchmark

De fire funktioner med det højeste CPU-forbrug er vores tjenesters funktioner, hvilket giver mening. Det samlede GC-forbrug er nu ~13%, mindre end halvdelen af det tidligere forbrug(!)

Vi kunne have stoppet her, men besluttede os for at afdække hvor og hvorfor vi allokerer så mange objekter. Mange gange er der en god grund til det (f.eks. i tilfælde af stream processing, hvor vi opretter masser af nye objekter for hver besked vi får og skal af med dem, fordi de er irrelevante for den næste besked), men der er tilfælde, hvor der er en nem måde at optimere og dramatisk mindske objektoprettelsen på.

For at starte, lad os køre den samme kommando som før med en lille ændring for at tage heap dump:

http://localhost:6060/debug/pprof/heap

For at forespørge på resultatfilen kan du køre følgende kommando i din kodemappe for at analysere dumpet:

go tool pprof -alloc_objects <HEAP.PROFILE.FILE>

vores snapshot så således ud:

Alt virkede fornuftigt bortset fra den tredje række, som er en overvågningsfunktion, der rapporterer til vores prometheus-eksportør i slutningen af hver Coralogix-regelparsingfase. For at komme dybere, kørte vi følgende kommando:

list <FunctionName>

For eksempel:

list reportRuleExecution

Og så fik vi følgende:

Leave a comment

Din e-mailadresse vil ikke blive publiceret.