För 10 år sedan stod Google inför en kritisk flaskhals som orsakades av extremt långa kompileringstider för C++ och behövde ett helt nytt sätt att lösa problemet. Googles ingenjörer tog sig an utmaningen genom att skapa ett nytt språk kallat Go (även kallat Golang). Det nya språket Go lånar de bästa delarna av C++ (framför allt dess prestanda- och säkerhetsfunktioner) och kombinerar det med hastigheten hos Python för att göra det möjligt för Go att snabbt använda flera kärnor och samtidigt kunna implementera samtidighet.

Här på Coralogix analyserar vi våra kunders loggar för att ge dem insikter, varningar och metadata om deras loggar i realtid. För att kunna göra det måste parsingfasen, som är mycket komplex och laddad med massor av regler för varje logglinjetjänst, vara extremt snabb. Det är en av anledningarna till att vi bestämde oss för att använda Go lang.

Den nya tjänsten körs nu på heltid i produktion och även om vi ser fantastiska resultat måste den köras på högpresterande maskiner. Över tiotals miljarder loggar analyseras varje dag av denna Go-tjänst som körs på en AWS m4.2xlarge-instans med 8 CPU:er och 36 GB minne.

I det här skedet hade vi kunnat sluta för dagen och känna oss nöjda med att allt går bra, men det är inte så vi gör här på Coralogix. Vi ville ha fler funktioner (prestanda osv.) med mindre resurser (AWS-instanser). För att kunna förbättra oss behövde vi först förstå karaktären på våra flaskhalsar och hur vi kan minska eller helt eliminera dem.

Vi bestämde oss för att köra lite Golang-profilering på vår tjänst och kontrollera exakt vad som orsakade hög CPU-förbrukning för att se om vi kan optimera.

Först har vi uppgraderat till den senaste stabila Go-versionen (en viktig del av programvarans livscykel). Vi hade Go version v1.12.4 och den senaste var 1.13.8. Version 1.13 hade enligt dokumentationen stora förbättringar i runtime-biblioteket och några andra komponenter som främst utnyttjade minnesanvändningen. I grund och botten var det bra att arbeta med den senaste stabila versionen och sparade oss en hel del arbete →

Därmed förbättrades minnesförbrukningen från cirka ~800MB till ~180MB.

För det andra, för att få en bättre förståelse för vår process och förstå var vi spenderar tid och resurser, började vi profilera.

Profilering av olika tjänster och programmeringsspråk kan tyckas vara komplext och skrämmande men det är faktiskt ganska enkelt i Go och kan beskrivas med några få kommandon. Go har ett dedikerat verktyg som heter ”pprof” som bör aktiveras i din app genom att lyssna på en rutt (standardport- 6060) och använda Go-paketet för att hantera http-anslutningar:

import _ "net/http/pprof"

Sedan initialiserar du följande i din huvudfunktion eller under ditt ruttpaket:

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

Nu kan du starta din tjänst och ansluta till

http://localhost:6060/debug/pprof

Full dokumentation av Go kan hittas här.

Standardprofileringen för pprof kommer att vara en 30 sekunders sampling av CPU-användningen. Det finns några olika vägar som möjliggör sampling för CPU-användning, heap-användning med mera.

Vi fokuserade på vår CPU-användning, så vi tog en 30 sekunders profilering i produktionen och upptäckte vad du ser i bilden nedan (påminnelse: detta är efter att ha uppgraderat vår Go-version och minskat de interna delarna av Go till ett minimum):

Go profilering – Coralogix

Som du kan se hittade vi massor av paketaktivitet under körning, vilket indikerade specifikt GC-aktivitet → Nästan 29% av vår CPU (bara de 20 mest använda objekten) används av GC. Eftersom Go GC är ganska snabb och ganska optimerad är den bästa metoden att inte ändra eller modifiera den och eftersom vår minnesförbrukning var mycket låg (jämfört med vår tidigare Go-version) var den främsta misstänkta orsaken en hög objektallokeringshastighet.

Om det är fallet finns det två saker vi kan göra:

  • Tunera Go GC-aktiviteten så att den anpassar sig till vårt tjänstebeteende, det vill säga – fördröja utlösningen så att GC aktiveras mindre ofta. Detta kommer att tvinga oss att kompensera med mer minne.
  • Hitta den funktion, det område eller den rad i vår kod som allokerar för många objekt.

Om vi tittade på vår instanstyp stod det klart att vi hade mycket minne över och att vi för närvarande är bundna av maskinens CPU. Så vi bytte bara ut det förhållandet. Golang har sedan sina tidiga dagar en flagga som de flesta utvecklare inte känner till, kallad GOGC. Denna flagga, med standardvärdet 100, talar helt enkelt om för systemet när GC ska utlösas. Standardvärdet kommer att utlösa GC-processen närhelst heap når 100 % av sin ursprungliga storlek. Om du ändrar värdet till ett högre tal fördröjer du GC-utlösningen och om du sänker värdet fördröjer du GC-utlösningen tidigare. Vi började göra benchmarking med några olika värden och den bästa prestandan för vårt syfte uppnåddes när vi använde: GOGC=2000.

Detta ökade omedelbart vår minnesanvändning från ~200MB till ~2,7GB (det är efter att minnesförbrukningen minskat på grund av vår Go-versionsuppdatering) och minskade vår CPU-användning med ~10%.
Följande skärmdump visar benchmarkresultaten:

GOGC =2000 resultat – Coralogix benchmark

De fyra mest CPU-förbrukande funktionerna är våra tjänsters funktioner, vilket är logiskt. Den totala GC-förbrukningen är nu ~13%, mindre än hälften av den tidigare förbrukningen(!)

Vi kunde ha stannat där, men bestämde oss för att avslöja var och varför vi allokerar så många objekt. Många gånger finns det en bra anledning till det (t.ex. vid strömbearbetning där vi skapar massor av nya objekt för varje meddelande vi får och måste göra oss av med dem eftersom de är irrelevanta för nästa meddelande), men det finns fall där det finns ett enkelt sätt att optimera och dramatiskt minska skapandet av objekt.

För att börja kör vi samma kommando som tidigare med en liten ändring för att ta heapdump:

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

För att fråga efter resultatfilen kan du köra följande kommando i din kodmapp för att analysera dumpningen:

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

Vår ögonblicksbild såg ut så här:

Allt verkade rimligt utom den tredje raden, som är en övervakningsfunktion som rapporterar till vår Prometheus-exportör i slutet av varje analysfas av Coralogix-regler. För att komma djupare körde vi följande kommando:

list <FunctionName>

Till exempel:

list reportRuleExecution

Och då fick vi följande:

Lämna en kommentar

Din e-postadress kommer inte publiceras.