Get best of the week

Wie wir unseren DNS-Server mit GO-Tools optimiert haben

In Erwartung des Starts eines neuen Streams im Kurs "Developer Golang" wurde eine Übersetzung von interessantem Material vorbereitet.



Unser autorisierender DNS-Server wird von Zehntausenden von Websites verwendet. Wir beantworten täglich Millionen von Anfragen. Heutzutage werden DNS-Angriffe immer häufiger, DNS ist ein wichtiger Bestandteil unseres Systems, und wir müssen sicherstellen, dass wir unter hoher Last gut funktionieren können.

dnsflood ist ein kleines Tool, das eine große Anzahl von udp-Anfragen generieren kann.

# timeout 20s ./dnsflood example.com 127.0.0.1 -p 2053

Die Systemüberwachung zeigte, dass die Speichernutzung unseres Dienstes so schnell zunahm, dass wir ihn stoppen mussten, da sonst OOM-Fehler auftreten würden. Es war wie ein Speicherverlustproblem; Es gibt verschiedene Gründe für "ähnliche" und "echte" Speicherlecks:

  • hängende Goroutinen
  • Missbrauch von Defer und Finalizer
  • Teilzeichenfolgen und Teilschnitte
  • globale Variablen

Dieser Beitrag enthält eine detaillierte Erläuterung verschiedener Lecks.

Bevor wir Schlussfolgerungen ziehen, führen wir zunächst eine Profilerstellung durch.

Godebug


Mithilfe einer Umgebungsvariablen können verschiedene Debugging-Tools aktiviert werden GODEBUG, wobei eine durch Kommas getrennte Liste von Paaren übergeben wird name=value.

Trace-Planer


Der Scheduler-Trace kann zur Laufzeit Informationen zum Verhalten der Goroutine bereitstellen. Um die Scheduler-Ablaufverfolgung zu aktivieren, führen Sie das Programm mit aus GODEBUG=schedtrace=100. Der Wert bestimmt die Ausgabezeit in ms.

$ GODEBUG=schedtrace=100 ./redins -c config.json
SCHED 2952ms: ... runqueue=3 [26 11 7 18 13 30 6 3 24 25 11 0]
SCHED 3053ms: ... runqueue=3 [0 0 0 0 0 0 0 0 4 0 21 0]
SCHED 3154ms: ... runqueue=0 [0 6 2 4 0 30 0 5 0 11 2 5]
SCHED 3255ms: ... runqueue=1 [0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 3355ms: ... runqueue=0 [1 0 0 0 0 0 0 0 0 0 0 0]
SCHED 3456ms: ... runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 3557ms: ... runqueue=0 [13 0 3 0 3 33 2 0 10 8 10 14]
SCHED 3657ms: ...runqueue=3 [14 1 0 5 19 54 9 1 0 1 29 0]
SCHED 3758ms: ... runqueue=0 [67 1 5 0 0 1 0 0 87 4 0 0]
SCHED 3859ms: ... runqueue=6 [0 0 3 6 0 0 0 0 3 2 2 19]
SCHED 3960ms: ... runqueue=0 [0 0 1 0 1 0 0 1 0 1 0 0]
SCHED 4060ms: ... runqueue=5 [4 0 5 0 1 0 0 0 0 0 0 0]
SCHED 4161ms: ... runqueue=0 [0 0 0 0 0 0 0 1 0 0 0 0]
SCHED 4262ms: ... runqueue=4 [0 128 21 172 1 19 8 2 43 5 139 37]
SCHED 4362ms: ... runqueue=0 [0 0 0 0 0 0 0 0 0 0 0 0]
SCHED 4463ms: ... runqueue=6 [0 28 23 39 4 11 4 11 25 0 25 0]
SCHED 4564ms: ... runqueue=354 [51 45 33 32 15 20 8 7 5 42 6 0]

runqueue ist die Länge der globalen Warteschlange der auszuführenden Goroutinen. Die Zahlen in Klammern geben die Länge der Prozesswarteschlange an.

Die ideale Situation ist, wenn alle Prozesse mit der Ausführung von Goroutinen beschäftigt sind und die moderate Länge der Ausführungswarteschlange gleichmäßig auf alle Prozesse verteilt ist:

SCHED 2449ms: gomaxprocs=12 idleprocs=0 threads=40 spinningthreads=1 idlethreads=1 runqueue=20 [20 20 20 20 20 20 20 20 20 20 20]

Wenn wir uns die Ausgabe von Schedtrace ansehen , sehen wir Zeiträume, in denen fast alle Prozesse inaktiv sind. Dies bedeutet, dass wir den Prozessor nicht mit voller Kapazität verwenden.

Garbage Collector Trace


Führen Sie das Programm mit einer Umgebungsvariablen aus, um die Ablaufverfolgung der Speicherbereinigung (GC) zu aktivieren GODEBUG=gctrace=1:

GODEBUG=gctrace=1 ./redins -c config1.json
.
.
.
gc 30 @3.727s 1%: 0.066+21+0.093 ms clock, 0.79+128/59/0+1.1 ms cpu, 67->71->45 MB, 76 MB goal, 12 P
gc 31 @3.784s 2%: 0.030+27+0.053 ms clock, 0.36+177/81/7.8+0.63 ms cpu, 79->84->55 MB, 90 MB goal, 12 P
gc 32 @3.858s 3%: 0.026+34+0.024 ms clock, 0.32+234/104/0+0.29 ms cpu, 96->100->65 MB, 110 MB goal, 12 P
gc 33 @3.954s 3%: 0.026+44+0.13 ms clock, 0.32+191/131/57+1.6 ms cpu, 117->123->79 MB, 131 MB goal, 12 P
gc 34 @4.077s 4%: 0.010+53+0.024 ms clock, 0.12+241/159/69+0.29 ms cpu, 142->147->91 MB, 158 MB goal, 12 P
gc 35 @4.228s 5%: 0.017+61+0.12 ms clock, 0.20+296/179/94+1.5 ms cpu, 166->174->105 MB, 182 MB goal, 12 P
gc 36 @4.391s 6%: 0.017+73+0.086 ms clock, 0.21+492/216/4.0+1.0 ms cpu, 191->198->122 MB, 210 MB goal, 12 P
gc 37 @4.590s 7%: 0.049+85+0.095 ms clock, 0.59+618/253/0+1.1 ms cpu, 222->230->140 MB, 244 MB goal, 12 P
.
.
.

Wie wir hier sehen, nimmt die Menge des verwendeten Speichers zu, und die Zeit, die gc benötigt, um seine Arbeit abzuschließen, nimmt ebenfalls zu. Dies bedeutet, dass wir mehr Speicher verbrauchen, als es verarbeiten kann.

Sie GODEBUGkönnen lernen , mehr über und einige andere golang Umgebungsvariablen hier .

Profiler aktivieren


go tool pprof- Ein Tool zum Analysieren und Profilieren von Daten. Es gibt zwei Möglichkeiten zur Konfiguration pprof: Rufen runtime/pprofSie beispielsweise direkt Funktionen in Ihrem Code auf pprof.StartCPUProfile()oder installieren Sie einen net/http/pprofhttp-Listener, um Daten von dort abzurufen, wie wir es getan haben. Der pprofRessourcenverbrauch ist sehr gering, sodass er sicher in der Entwicklung verwendet werden kann. Der Profilendpunkt sollte jedoch nicht öffentlich verfügbar sein, da vertrauliche Daten offengelegt werden können.

Für die zweite Option müssen wir lediglich das Paket "net / http / pprof" importieren :

import (
  _ "net/http/pprof"
)

Fügen Sie dann einen http-Listener hinzu:

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

Pprof hat mehrere Standardprofile:

  • Zuordnungen : Ruft alle früheren Speicherzuordnungen ab
  • block : Stack-Trace, der zum Blockieren von Synchronisationsprimitiven führte
  • Goroutine : Stapelverfolgung aller aktuellen Goroutinen
  • Heap : Speicherzuordnungen von Live-Objekten abrufen.
  • Mutex : Stapelverfolgung von widersprüchlichen Mutex-Inhabern
  • Profil : Prozessorprofil.
  • threadcreate : Ein Stack-Trace, der zur Erstellung neuer Threads im Betriebssystem führte
  • trace : Verfolgt die Ausführung des aktuellen Programms.

Hinweis: Der Ablaufverfolgungsendpunkt ist im Gegensatz zu allen anderen Endpunkten ein Ablaufverfolgungsprofil und kein pprof . Sie können ihn stattdessen mithilfe der Go-Tool-Ablaufverfolgung anzeigengo tool pprof .
Nachdem alles fertig ist, können wir uns die verfügbaren Tools ansehen.

Prozessor-Profiler


‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍$ go tool pprof http://localhost:6060/debug/pprof/profile?seconds=10


Der Prozessor-Profiler läuft standardmäßig 30 Sekunden lang (wir können dies durch Einstellen des Parameters ändern seconds) und sammelt alle 100 Millisekunden Samples. Danach wechselt er in den interaktiven Modus. Die am häufigsten verwendeten Befehlen zur Verfügung top, list, web.

Verwenden Sie top ndiese Option, um die heißesten Einträge im Textformat anzuzeigen. Außerdem gibt es zwei Optionen zum Sortieren der Ausgabe: -cumfür die kumulative Reihenfolge und -flat.

(pprof) top 10 -cum
Showing nodes accounting for 1.50s, 6.19% of 24.23s total
Dropped 347 nodes (cum <= 0.12s)
Showing top 10 nodes out of 186
flat  flat%   sum%  cum   cum%
0.03s 0.12% 0.12% 16.7s 69.13% (*Server).serveUDPPacket
0.05s 0.21% 0.33% 15.6s 64.51% (*Server).serveDNS
0     0%    0.33% 14.3s 59.10% (*ServeMux).ServeDNS
0     0%    0.33% 14.2s 58.73% HandlerFunc.ServeDNS
0.01s 0.04% 0.37% 14.2s 58.73% main.handleRequest
0.07s 0.29% 0.66% 13.5s 56.00% (*DnsRequestHandler).HandleRequest
0.99s 4.09% 4.75% 7.56s 31.20% runtime.gentraceback
0.02s 0.08% 4.83% 7.02s 28.97% runtime.systemstack
0.31s 1.28% 6.11% 6.62s 27.32% runtime.mallocgc
0.02s 0.08% 6.19% 6.35s 26.21% (*DnsRequestHandler).FindANAME
(pprof)

verwenden list, um die Funktion zu erkunden.

(pprof) list handleRequest
Total: 24.23s
ROUTINE ======================== main.handleRequest in /home/arash/go/src/arvancloud/redins/redins.go
     10ms     14.23s (flat, cum) 58.73% of Total
        .          .     35: l          *handler.RateLimiter
        .          .     36: configFile string
        .          .     37:)
        .          .     38:
        .          .     39:func handleRequest(w dns.ResponseWriter, r *dns.Msg) {
     10ms      610ms     40: context := handler.NewRequestContext(w, r)
        .       50ms     41: logger.Default.Debugf("handle request: [%d] %s %s", r.Id, context.RawName(), context.Type())
        .          .     42:
        .          .     43: if l.CanHandle(context.IP()) {
        .     13.57s     44:  h.HandleRequest(context)
        .          .     45: } else {
        .          .     46:  context.Response(dns.RcodeRefused)
        .          .     47: }
        .          .     48:}
        .          .     49:
(pprof)

Das Team weberstellt ein SVG-Diagramm kritischer Bereiche und öffnet es im Browser.

(pprof)web handleReques



Ein großer Zeitaufwand für GC-Funktionen führt runtime.mallocgchäufig zu einer erheblichen Speicherzuweisung, die den Garbage Collector zusätzlich belasten und die Latenz erhöhen kann.

Ein großer Zeitaufwand für Synchronisationsmechanismen wie runtime.chansendoder runtime.lockkann ein Zeichen für einen Konflikt sein.

Ein großer Zeitaufwand syscall.Read/Writebedeutet eine übermäßige Verwendung von E / A-Vorgängen.

Speicherprofiler


$ go tool pprof http://localhost:6060/debug/pprof/allocs


Standardmäßig wird die Lebensdauer des zugewiesenen Speichers angezeigt. Wir können die Anzahl der ausgewählten Objekte mithilfe -alloc_objectsanderer nützlicher Optionen anzeigen: -iuse_objectsund -inuse_spacezur Überprüfung des Live- Speichers.

Wenn Sie den Speicherverbrauch reduzieren möchten, müssen Sie normalerweise nachsehen -inuse_space, aber wenn Sie die Latenz reduzieren möchten, achten Sie auf -alloc_objectsgenügend Laufzeit / Ladezeit.

Identifizierung eines Engpasses


Es ist wichtig, zuerst die Art des Engpasses (Prozessor, E / A, Speicher) zu bestimmen, mit dem wir uns befassen. Neben Profilern gibt es noch eine andere Art von Werkzeug.

go tool tracekann zeigen, was Goroutinen im Detail tun. Um ein Trace-Beispiel zu erfassen, müssen wir eine http-Anforderung an den Trace-Endpunkt senden:

$ curl http://localhost:6060/debug/pprof/trace?seconds=5 --output trace.out

Die generierte Datei kann mit dem Trace-Tool angezeigt werden:

$ go tool trace trace.out
2019/12/25 15:30:50 Parsing trace...
2019/12/25 15:30:59 Splitting trace...
2019/12/25 15:31:10 Opening browser. Trace viewer is listening on http://127.0.0.1:42703

Go Tool Trace ist eine Webanwendung, die das Chrome DevTools-Protokoll verwendet und nur mit Chrome-Browsern kompatibel ist. Die Hauptseite sieht

ungefähr so aus: Trace anzeigen (0s-409.575266ms)
Trace anzeigen (411.075559ms-747.252311ms)
Trace anzeigen (747.252311ms-1.234968945s)
Trace anzeigen (1.234968945s-1.774245108s)
Trace anzeigen (1.774245484s-2.111339514s)
Trace anzeigen (2.111339514s-2.674030898s)
Trace anzeigen (2.674031362s-3.044145798s)
Trace anzeigen (3.044145798s-3.458795252s)
Trace anzeigen (3.43953778s-4.075080634s)
Trace anzeigen (4.075081098s-
4.439271287s) -4.814869651s)
Trace anzeigen (4.814869651s-5.253597835s)

Goroutine-Analyse
Netzwerkblockierungsprofil ()
Synchronisationsblockierungsprofil ()
Syscall-Blockierungsprofil ()
Scheduler-Latenzzeitprofil ()
Benutzerdefinierte Aufgaben
Benutzerdefinierte Regionen
Minimale Mutatorauslastung

Die Ablaufverfolgung teilt die Ablaufverfolgungszeit auf, damit Ihr Browser damit umgehen kann.



Hier gibt es eine große Datenmenge, die sie fast unlesbar macht, wenn Wir wissen nicht, wonach wir suchen. Lassen wir es jetzt.

Der folgende Link auf der Hauptseite ist "Goroutinenanalyse" , der die verschiedenen Arten von Arbeitsgoroutinen im Programm während des Verfolgungszeitraums zeigt :

Goroutines:
github.com/miekg/dns.(*Server).serveUDPPacket N=441703
runtime.gcBgMarkWorker N=12
github.com/karlseguin/ccache.(*Cache).worker N=2
main.Start.func1 N=1
runtime.bgsweep N=1
arvancloud/redins/handler.NewHandler.func2 N=1
runtime/trace.Start.func1 N=1
net/http.(*conn).serve N=1
runtime.timerproc N=3
net/http.(*connReader).backgroundRead N=1
N=40

Klicken Sie auf das erste Element mit N = 441703 , das bekommen wir:


Goroutin-Analyse

Das ist sehr interessant. Die meisten Vorgänge benötigen fast keine Zeit, und die meiste Zeit wird im Synchronisierungsblock verbracht. Schauen wir uns eines davon genauer an:


Goroutine-Trace-Muster

Es scheint, dass unser Programm fast immer inaktiv ist. Von hier aus können wir direkt zum Schlosswerkzeug gehen; Das Sperrenprofil ist standardmäßig deaktiviert. Wir müssen es zuerst in unserem Code aktivieren:

runtime.SetBlockProfileRate(1)

Jetzt können wir eine Auswahl an Schlössern erhalten:

$ go tool pprof http://localhost:6060/debug/pprof/block
(pprof) top
Showing nodes accounting for 16.03wks, 99.75% of 16.07wks total
Dropped 87 nodes (cum <= 0.08wks)
Showing top 10 nodes out of 27
     flat  flat%   sum%        cum   cum%
 10.78wks 67.08% 67.08%   10.78wks 67.08%  internal/poll.(*fdMutex).rwlock
  5.25wks 32.67% 99.75%    5.25wks 32.67%  sync.(*Mutex).Lock
        0     0% 99.75%    5.25wks 32.67%  arvancloud/redins/handler.(*DnsRequestHandler).Filter
        0     0% 99.75%    5.25wks 32.68%  arvancloud/redins/handler.(*DnsRequestHandler).FindANAME
        0     0% 99.75%   16.04wks 99.81%  arvancloud/redins/handler.(*DnsRequestHandler).HandleRequest
        0     0% 99.75%   10.78wks 67.08%  arvancloud/redins/handler.(*DnsRequestHandler).Response
        0     0% 99.75%   10.78wks 67.08%  arvancloud/redins/handler.(*RequestContext).Response
        0     0% 99.75%    5.25wks 32.67%  arvancloud/redins/handler.ChooseIp
        0     0% 99.75%   16.04wks 99.81%  github.com/miekg/dns.(*ServeMux).ServeDNS
        0     0% 99.75%   16.04wks 99.81%  github.com/miekg/dns.(*Server).serveDNS
(pprof)

Hier haben wir zwei verschiedene Sperren ( poll.fdMutex und sync.Mutex ), die für fast 100% der Sperren verantwortlich sind. Dies bestätigt unsere Annahme über einen Sperrkonflikt. Jetzt müssen wir nur noch herausfinden, wo dies geschieht:

(pprof) svg lock

Dieser Befehl erstellt ein Vektordiagramm aller Knoten, die Konflikte berücksichtigen, wobei der Schwerpunkt auf Blockierungsfunktionen liegt:


svg-Diagramm des blockierenden Endpunkts

Wir können das gleiche Ergebnis vom Goroutine-Endpunkt erhalten:

$ go tool pprof http://localhost:6060/debug/pprof/goroutine

und dann:

(pprof) top
Showing nodes accounting for 294412, 100% of 294424 total
Dropped 84 nodes (cum <= 1472)
Showing top 10 nodes out of 32
     flat  flat%   sum%        cum   cum%
   294404   100%   100%     294404   100%  runtime.gopark
        8 0.0027%   100%     294405   100%  github.com/miekg/dns.(*Server).serveUDPPacket
        0     0%   100%      58257 19.79%  arvancloud/redins/handler.(*DnsRequestHandler).Filter
        0     0%   100%      58259 19.79%  arvancloud/redins/handler.(*DnsRequestHandler).FindANAME
        0     0%   100%     293852 99.81%  arvancloud/redins/handler.(*DnsRequestHandler).HandleRequest
        0     0%   100%     235406 79.95%  arvancloud/redins/handler.(*DnsRequestHandler).Response
        0     0%   100%     235406 79.95%  arvancloud/redins/handler.(*RequestContext).Response
        0     0%   100%      58140 19.75%  arvancloud/redins/handler.ChooseIp
        0     0%   100%     293852 99.81%  github.com/miekg/dns.(*ServeMux).ServeDNS
        0     0%   100%     293900 99.82%  github.com/miekg/dns.(*Server).serveDNS
(pprof)

Fast alle unsere Programme befinden sich in runtime.gopark. Es ist ein Go-Scheduler, der Goroutinen schläft. Ein sehr häufiger Grund dafür ist ein Sperrkonflikt

(pprof) svg gopark


svg-graph des endpunkts goroutin

Hier sehen wir zwei Konfliktquellen:

UDPConn.WriteMsg ()


Es scheint, dass alle Antworten auf dieselbe FD (daher die Sperre) geschrieben werden. Dies ist sinnvoll, da alle dieselbe Quelladresse haben.

Wir haben ein kleines Experiment mit verschiedenen Lösungen durchgeführt und am Ende beschlossen, mehrere Listener zu verwenden, um die Last auszugleichen. Auf diese Weise kann das Betriebssystem eingehende Anforderungen zwischen verschiedenen Verbindungen ausgleichen und Konflikte reduzieren.

Rand ()


Es sieht so aus, als ob es eine Sperre für reguläre Math / Rand-Funktionen gibt (mehr dazu hier ). Dies kann einfach mit Hilfe Rand.New()eines Zufallszahlengenerators behoben werden, der einen nicht blockierenden Wrapper erstellt.

rg := rand.New(rand.NewSource(int64(time.Now().Nanosecond())))

Es ist ein bisschen besser, aber das Erstellen einer neuen Quelle ist jedes Mal teuer. Kann man es noch besser machen? In unserem Fall brauchen wir wirklich keine Zufallszahl. Wir brauchen nur eine gleichmäßige Verteilung, um die Last auszugleichen, und es stellt sich heraus, dass sie Time.Nanoseconds()zu uns passt. Nachdem

wir alle unnötigen Sperren entfernt haben, schauen wir uns die Ergebnisse an:


Goroutin-Analyse

Sieht besser aus, aber die meiste Zeit dauert es, um die Synchronisation zu sperren. Werfen wir einen Blick auf das Synchronisationssperrprofil auf der Hauptseite der Trace-Benutzeroberfläche:


Zeitleiste

für die Synchronisationssperre Schauen wir uns die Boost-Funktion ccachevom Sperrendpunkt aus an pprof:

(pprof) list promote
ROUTINE ======================== github.com/karlseguin/ccache.(*Cache).promote in ...
        0   9.66days (flat, cum) 99.70% of Total
        .          .    155: h.Write([]byte(key))
        .          .    156: return c.buckets[h.Sum32()&c.bucketMask]
        .          .    157:}
        .          .    158:
        .          .    159:func (c *Cache) promote(item *Item) {
        .   9.66days    160: c.promotables <- item
        .          .    161:}
        .          .    162:
        .          .    163:func (c *Cache) worker() {
        .          .    164: defer close(c.donec)
        .          .    165:

Alle Anrufe ccache.Get()enden in einem Kanal c.promotables. Caching ist ein wichtiger Teil unseres Service. Wir sollten andere Optionen in Betracht ziehen. In Dgraph gibt es einen ausgezeichneten Artikel über den Cache-Status! Go , sie haben auch ein ausgezeichnetes Caching-Modul namens Ristretto . Leider unterstützt Ristretto die Ttl-basierte Version noch nicht. Wir könnten dieses Problem umgehen, indem wir ein sehr großes verwenden MaxCostund den Timeout-Wert in unserer Cache-Struktur beibehalten (wir möchten veraltete Daten im Cache behalten). Lassen Sie uns das Ergebnis bei Verwendung von Ristretto sehen:


Goroutin-Analyse

Großartig!

Wir konnten die maximale Laufzeit von Gorutin von 5000 ms auf 22 ms reduzieren. Der größte Teil der Ausführungszeit wird jedoch zwischen "Synchronisationssperre" und "Warten auf den Scheduler" aufgeteilt. Mal sehen, ob wir etwas dagegen tun können: die


Zeitleiste für die Synchronisationssperre

Wir können wenig damit fdMutex.rwlockanfangen. Konzentrieren wir uns jetzt auf eine andere: gcMarkDone, die für 53% der Blockierungszeit verantwortlich ist. Diese Funktion ist Teil des Speicherbereinigungsprozesses. Ihre Anwesenheit im kritischen Bereich ist oft ein Zeichen dafür, dass wir gc überladen.

Zuordnungsoptimierung


An dieser Stelle kann es hilfreich sein zu sehen, wie die Speicherbereinigung funktioniert. Go verwendet einen Mark-and-Sweep-Picker. Es verfolgt alles, was ausgewählt wurde, und sobald es die doppelte Größe (oder einen anderen Wert, auf den GOGC eingestellt ist) der Größe der vorherigen Größe erreicht, beginnt die GC-Bereinigung. Die Bewertung erfolgt in drei Schritten:

  • Markierungseinstellung (STW)
  • Markierung (parallel)
  • Beschriftungsende (STW)

Die Phasen Stop The World (STW) stoppen den gesamten Prozess, obwohl sie normalerweise sehr kurz sind. Kontinuierliche Zyklen können die Dauer verlängern. Dies liegt daran, dass derzeit (siehe Version 1.13) Goroutinen nur an den Punkten des Funktionsaufrufs ersetzt werden. Daher ist für einen kontinuierlichen Zyklus eine beliebig lange Pausenzeit möglich, da der GC erwartet, dass alle Goroutinen anhalten.

Während des Markierens verbraucht gc ungefähr 25% GOMAXPROCS, aber zusätzliche Hilfsfunktionen können zwangsweise hinzugefügt werden, um den Markierungsassistenten zu unterstützen . Dies geschieht, wenn die sich schnell bewegende Goroutine die Hintergrundmarkierung übertrifft, um die durch gc verursachte Verzögerung zu verringern. Wir müssen den Heap-Verbrauch minimieren.

Zwei Dinge zu beachten:

  • Die Anzahl der Zuweisungen ist wichtiger als die Größe (beispielsweise verursachen 1000 Speicherzuweisungen aus einer 20-Byte-Struktur eine viel höhere Belastung des Heapspeichers als eine einzelne Zuweisung von 20.000 Bytes).
  • Im Gegensatz zu Sprachen wie C / C ++ landen nicht alle Speicherzuordnungen auf dem Heap. Der go-Compiler entscheidet, ob die Variable auf den Heap verschoben wird oder ob sie innerhalb des Stapelrahmens platziert werden kann. Im Gegensatz zu auf dem Heap zugewiesenen Variablen laden auf dem Stapel zugewiesene Variablen gc nicht.

Weitere Informationen zum Go-Speichermodell und zur GC-Architektur finden Sie in dieser Präsentation .

Um die Speicherzuordnung zu optimieren, verwenden wir das go-Toolkit:

  • Prozessor-Profiler zum Auffinden heißer Verteilungen;
  • Speicherprofiler zur Verfolgung von Zuordnungen;
  • Tracer für Muster; Gc
  • Escape-Analyse, um herauszufinden, warum die Zuordnung erfolgt.

Beginnen wir mit dem Prozessor-Profiler:

$ go tool pprof http://localhost:6060/debug/pprof/profile?seconds=20
(pprof) top 20 -cum
Showing nodes accounting for 7.27s, 29.10% of 24.98s total
Dropped 315 nodes (cum <= 0.12s)
Showing top 20 nodes out of 201
     flat  flat%   sum%        cum   cum%
        0     0%     0%     16.42s 65.73%  github.com/miekg/dns.(*Server).serveUDPPacket
    0.02s  0.08%  0.08%     16.02s 64.13%  github.com/miekg/dns.(*Server).serveDNS
    0.02s  0.08%  0.16%     13.69s 54.80%  github.com/miekg/dns.(*ServeMux).ServeDNS
    0.01s  0.04%   0.2%     13.48s 53.96%  github.com/miekg/dns.HandlerFunc.ServeDNS
    0.02s  0.08%  0.28%     13.47s 53.92%  main.handleRequest
    0.24s  0.96%  1.24%     12.50s 50.04%  arvancloud/redins/handler.(*DnsRequestHandler).HandleRequest
    0.81s  3.24%  4.48%      6.91s 27.66%  runtime.gentraceback
    3.82s 15.29% 19.78%      5.48s 21.94%  syscall.Syscall
    0.02s  0.08% 19.86%      5.44s 21.78%  arvancloud/redins/handler.(*DnsRequestHandler).Response
    0.06s  0.24% 20.10%      5.25s 21.02%  arvancloud/redins/handler.(*RequestContext).Response
    0.03s  0.12% 20.22%      4.97s 19.90%  arvancloud/redins/handler.(*DnsRequestHandler).FindANAME
    0.56s  2.24% 22.46%      4.92s 19.70%  runtime.mallocgc
    0.07s  0.28% 22.74%      4.90s 19.62%  github.com/miekg/dns.(*response).WriteMsg
    0.04s  0.16% 22.90%      4.40s 17.61%  github.com/miekg/dns.(*response).Write
    0.01s  0.04% 22.94%      4.36s 17.45%  github.com/miekg/dns.WriteToSessionUDP
    1.43s  5.72% 28.66%      4.30s 17.21%  runtime.pcvalue
    0.01s  0.04% 28.70%      4.15s 16.61%  runtime.newstack
    0.06s  0.24% 28.94%      4.09s 16.37%  runtime.copystack
    0.01s  0.04% 28.98%      4.05s 16.21%  net.(*UDPConn).WriteMsgUDP
    0.03s  0.12% 29.10%      4.04s 16.17%  net.(*UDPConn).writeMsg

Wir sind besonders an verwandten Funktionen interessiert, mallocgchier hilft bei Tags

(pprof) svg mallocgc



Wir können die Verteilung mithilfe des Endpunkts verfolgen. Die allocOption alloc_objectbedeutet die Gesamtzahl der Zuweisungen. Es gibt andere Optionen für die Verwendung von Speicher und Zuordnungsspeicher.

$ go tool pprof -alloc_objects http://localhost:6060/debug/pprof/allocs
(pprof) top -cum
Active filters:
  show=handler
Showing nodes accounting for 58464353, 59.78% of 97803168 total
Dropped 1 node (cum <= 489015)
Showing top 10 nodes out of 19
     flat  flat%   sum%        cum   cum%
 15401215 15.75% 15.75%   70279955 71.86%  arvancloud/redins/handler.(*DnsRequestHandler).HandleRequest
  2392100  2.45% 18.19%   27198697 27.81%  arvancloud/redins/handler.(*DnsRequestHandler).FindANAME
   711174  0.73% 18.92%   14936976 15.27%  arvancloud/redins/handler.(*DnsRequestHandler).Filter
        0     0% 18.92%   14161410 14.48%  arvancloud/redins/handler.(*DnsRequestHandler).Response
 14161410 14.48% 33.40%   14161410 14.48%  arvancloud/redins/handler.(*RequestContext).Response
  7284487  7.45% 40.85%   11118401 11.37%  arvancloud/redins/handler.NewRequestContext
 10439697 10.67% 51.52%   10439697 10.67%  arvancloud/redins/handler.reverseZone
        0     0% 51.52%   10371430 10.60%  arvancloud/redins/handler.(*DnsRequestHandler).FindZone
  2680723  2.74% 54.26%    8022046  8.20%  arvancloud/redins/handler.(*GeoIp).GetSameCountry
  5393547  5.51% 59.78%    5393547  5.51%  arvancloud/redins/handler.(*DnsRequestHandler).LoadLocation

Von nun an können wir die Liste für jede Funktion verwenden und prüfen, ob wir die Speicherzuordnung reduzieren können. Lassen Sie uns überprüfen:

printf-ähnliche Funktionen

(pprof) list handleRequest
Total: 97803168
ROUTINE ======================== main.handleRequest in /home/arash/go/src/arvancloud/redins/redins.go
  2555943   83954299 (flat, cum) 85.84% of Total
        .          .     35: l          *handler.RateLimiter
        .          .     36: configFile string
        .          .     37:)
        .          .     38:
        .          .     39:func handleRequest(w dns.ResponseWriter, r *dns.Msg) {
        .   11118401     40: context := handler.NewRequestContext(w, r)
  2555943    2555943     41: logger.Default.Debugf("handle request: [%d] %s %s", r.Id, context.RawName(), context.Type())
        .          .     42:
        .          .     43: if l.CanHandle(context.IP()) {
        .   70279955     44:  h.HandleRequest(context)
        .          .     45: } else {
        .          .     46:  context.Response(dns.RcodeRefused)
        .          .     47: }
        .          .     48:}
        .          .     49:

Zeile 41 ist besonders interessant, auch wenn das Debuggen deaktiviert ist und dort noch Speicher zugewiesen ist. Wir können die Escape-Analyse verwenden, um sie genauer zu untersuchen.

Das Go Escape Analysis Tool ist eigentlich ein Compiler-Flag

$ go build -gcflags '-m'

Sie können ein weiteres -m hinzufügen, um weitere Informationen zu erhalten.

$ go build -gcflags '-m '

Verwenden Sie für eine bequemere Benutzeroberfläche view-annotated-file .

$ go build -gcflags '-m'
.
.
.
../redins.go:39:20: leaking param: w
./redins.go:39:42: leaking param: r
./redins.go:41:55: r.MsgHdr.Id escapes to heap
./redins.go:41:75: context.RawName() escapes to heap
./redins.go:41:91: context.Request.Type() escapes to heap
./redins.go:41:23: handleRequest []interface {} literal does not escape
./redins.go:219:17: leaking param: path
.
.
.

Hier gehen alle Parameter Debugfauf Heap. Dies liegt an der Art und Weise der Bestimmung Debugf:

func (l *EventLogger) Debugf(format string, args ...interface{})

Alle Parameter werden argsin einen Typ konvertiert, der interface{}immer auf dem Heap gespeichert wird. Wir können entweder die Debug-Protokolle löschen oder eine Bibliothek von Protokollen mit einer Nullverteilung verwenden , z. B. zerolog .

Weitere Informationen zur Fluchtanalyse finden Sie unter „Zuordnungseffizienz in Golang“ .

Arbeite mit Strings

(pprof) list reverseZone
Total: 100817064
ROUTINE ======================== arvancloud/redins/handler.reverseZone in /home/arash/go/src/arvancloud/redins/handler/handler.go
  6127746   10379086 (flat, cum) 10.29% of Total
        .          .    396:  logger.Default.Warning("log queue is full")
        .          .    397: }
        .          .    398:}
        .          .    399:
        .          .    400:func reverseZone(zone string) string {
        .    4251340    401: x := strings.Split(zone, ".")
        .          .    402: var y string
        .          .    403: for i := len(x) - 1; i >= 0; i-- {
  6127746    6127746    404:  y += x[i] + "."
        .          .    405: }
        .          .    406: return y
        .          .    407:}
        .          .    408:
        .          .    409:func (h *DnsRequestHandler) LoadZones() {
(pprof)

Da eine Zeile in Go unveränderlich ist, führt das Erstellen einer temporären Zeile zur Speicherzuweisung. Ab Go 1.10 können Sie strings.Builderdamit eine Zeichenfolge erstellen.

(pprof) list reverseZone
Total: 93437002
ROUTINE ======================== arvancloud/redins/handler.reverseZone in /home/arash/go/src/arvancloud/redins/handler/handler.go
        0    7580611 (flat, cum)  8.11% of Total
        .          .    396:  logger.Default.Warning("log queue is full")
        .          .    397: }
        .          .    398:}
        .          .    399:
        .          .    400:func reverseZone(zone string) string {
        .    3681140    401: x := strings.Split(zone, ".")
        .          .    402: var sb strings.Builder
        .    3899471    403: sb.Grow(len(zone)+1)
        .          .    404: for i := len(x) - 1; i >= 0; i-- {
        .          .    405:  sb.WriteString(x[i])
        .          .    406:  sb.WriteByte('.')
        .          .    407: }
        .          .    408: return sb.String()

Da uns der Wert der invertierten Linie nicht wichtig ist, können wir ihn beseitigen Split(), indem wir einfach die gesamte Linie umdrehen.

(pprof) list reverseZone
Total: 89094296
ROUTINE ======================== arvancloud/redins/handler.reverseZone in /home/arash/go/src/arvancloud/redins/handler/handler.go
  3801168    3801168 (flat, cum)  4.27% of Total
        .          .    400:func reverseZone(zone string) []byte {
        .          .    401: runes := []rune("." + zone)
        .          .    402: for i, j := 0, len(runes)-1; i < j; i, j = i+1, j-1 {
        .          .    403:  runes[i], runes[j] = runes[j], runes[i]
        .          .    404: }
  3801168    3801168    405: return []byte(string(runes))
        .          .    406:}
        .          .    407:
        .          .    408:func (h *DnsRequestHandler) LoadZones() {
        .          .    409: h.LastZoneUpdate = time.Now()
        .          .    410: zones, err := h.Redis.SMembers("redins:zones")

Lesen Sie mehr über die Arbeit mit Strings hier .

sync.Pool


(pprof) list GetASN
Total: 69005282
ROUTINE ======================== arvancloud/redins/handler.(*GeoIp).GetASN in /home/arash/go/src/arvancloud/redins/handler/geoip.go
  1146897    1146897 (flat, cum)  1.66% of Total
        .          .    231:func (g *GeoIp) GetASN(ip net.IP) (uint, error) {
  1146897    1146897    232: var record struct {
        .          .    233:  AutonomousSystemNumber uint `maxminddb:"autonomous_system_number"`
        .          .    234: }
        .          .    235: err := g.ASNDB.Lookup(ip, &record)
        .          .    236: if err != nil {
        .          .    237:  logger.Default.Errorf("lookup failed : %s", err)
(pprof) list GetGeoLocation
Total: 69005282
ROUTINE ======================== arvancloud/redins/handler.(*GeoIp).GetGeoLocation in /home/arash/go/src/arvancloud/redins/handler/geoip.go
  1376298    3604572 (flat, cum)  5.22% of Total
        .          .    207:
        .          .    208:func (g *GeoIp) GetGeoLocation(ip net.IP) (latitude float64, longitude float64, country string, err error) {
        .          .    209: if !g.Enable || g.CountryDB == nil {
        .          .    210:  return
        .          .    211: }
  1376298    1376298    212: var record struct {
        .          .    213:  Location struct {
        .          .    214:   Latitude        float64 `maxminddb:"latitude"`
        .          .    215:   LongitudeOffset uintptr `maxminddb:"longitude"`
        .          .    216:  } `maxminddb:"location"`
        .          .    217:  Country struct {
        .          .    218:   ISOCode string `maxminddb:"iso_code"`
        .          .    219:  } `maxminddb:"country"`
        .          .    220: }
        .          .    221: // logger.Default.Debugf("ip : %s", ip)
        .          .    222: if err := g.CountryDB.Lookup(ip, &record); err != nil {
        .          .    223:  logger.Default.Errorf("lookup failed : %s", err)
        .          .    224:  return 0, 0, "", err
        .          .    225: }
        .    2228274    226: _ = g.CountryDB.Decode(record.Location.LongitudeOffset, &longitude)
        .          .    227: // logger.Default.Debug("lat = ", record.Location.Latitude, " lang = ", longitude, " country = ", record.Country.ISOCode)
        .          .    228: return record.Location.Latitude, longitude, record.Country.ISOCode, nil
        .          .    229:}
        .          .    230:
        .          .    231:func (g *GeoIp) GetASN(ip net.IP) (uint, error) {

Wir verwenden maxmiddb- Funktionen , um Geolokalisierungsdaten abzurufen . Diese Funktionen werden interface{}als Parameter verwendet, die, wie wir bereits gesehen haben, Haufenschüsse verursachen können.

Wir können sync.Poolausgewählte, aber nicht verwendete Elemente für die spätere Wiederverwendung zwischenspeichern.

type MMDBGeoLocation struct {
  Coordinations struct {
     Latitude        float64 `maxminddb:"latitude"`
     Longitude       float64
     LongitudeOffset uintptr `maxminddb:"longitude"`
  } `maxminddb:"location"`
  Country struct {
     ISOCode string `maxminddb:"iso_code"`
  } `maxminddb:"country"`
}

type MMDBASN struct {
  AutonomousSystemNumber uint `maxminddb:"autonomous_system_number"`
}
func (g *GeoIp) GetGeoLocation(ip net.IP) (*MMDBGeoLocation, error) {
  if !g.Enable || g.CountryDB == nil {
     return nil, EMMDBNotAvailable
  }
  var record *MMDBGeoLocation = g.LocationPool.Get().(*MMDBGeoLocation)
  logger.Default.Debugf("ip : %s", ip)
  if err := g.CountryDB.Lookup(ip, &record); err != nil {
     logger.Default.Errorf("lookup failed : %s", err)
     return nil, err
  }
  _ = g.CountryDB.Decode(record.Coordinations.LongitudeOffset, &record.Coordinations.Longitude)
  logger.Default.Debug("lat = ", record.Coordinations.Latitude, " lang = ", record.Coordinations.Longitude, " country = ", record.Country.ISOCode)
  return record, nil
}

func (g *GeoIp) GetASN(ip net.IP) (uint, error) {
  var record *MMDBASN = g.AsnPool.Get().(*MMDBASN)
  err := g.ASNDB.Lookup(ip, record)
  if err != nil {
     logger.Default.Errorf("lookup failed : %s", err)
     return 0, err
  }
  logger.Default.Debug("asn = ", record.AutonomousSystemNumber)
  return record.AutonomousSystemNumber, nil
}

Mehr über sync.Pool hier .

Es gibt viele andere mögliche Optimierungen, aber im Moment scheinen wir bereits genug getan zu haben. Weitere Informationen zu Speicheroptimierungstechniken finden Sie unter Allokationseffizienz in leistungsstarken Go-Diensten .

Ergebnisse


Um die Ergebnisse der Speicheroptimierung zu visualisieren, verwenden wir ein Diagramm mit dem go tool traceTitel "Minimum Mutator Utilization". Hier bedeutet Mutator nicht gc.

Vor der Optimierung:



Hier haben wir ein Fenster von ungefähr 500 Millisekunden ohne effiziente Nutzung (gc verbraucht alle Ressourcen), und wir werden auf lange Sicht niemals eine 80% ige effektive Nutzung erhalten. Wir möchten, dass das Fenster ohne effektive Nutzung so klein wie möglich ist und so schnell wie möglich eine 100% ige Nutzung erreicht wird.

Nach der Optimierung:



Fazit


Mithilfe von Go-Tools konnten wir unseren Service optimieren, um eine große Anzahl von Anforderungen zu bearbeiten und die Systemressourcen besser zu nutzen.

Sie können unseren Quellcode auf GitHub sehen . Hier ist eine nicht optimierte Version und hier ist eine optimierte.

Es wird auch nützlich sein



Das ist alles. Wir sehen uns auf dem Kurs !

Source: https://habr.com/ru/post/undefined/

More articles:


All Articles