🚀 🧑🏼‍🤝‍🧑🏻 ♏️ Comment nous avons optimisé notre serveur DNS à l'aide des outils GO 🗓️ 👘 👝

En prévision du début d'un nouveau flux sur le cours "Developer Golang" a préparé une traduction de matériel intéressant.

Notre serveur DNS faisant autorité est utilisé par des dizaines de milliers de sites Web. Nous répondons quotidiennement à des millions de requêtes. De nos jours, les attaques DNS sont de plus en plus courantes, le DNS est une partie importante de notre système et nous devons nous assurer que nous pouvons bien fonctionner sous une charge élevée.

dnsflood est un petit outil qui peut générer un grand nombre de requêtes udp.

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

La surveillance du système a montré que l'utilisation de la mémoire de notre service augmentait si rapidement que nous devions l'arrêter, sinon nous rencontrerions des erreurs de MOO. C'était comme un problème de fuite de mémoire; Il existe différentes raisons pour les fuites de mémoire «similaires» et «réelles» en cours:

goroutines suspendues
mauvaise utilisation du report et du finaliseur
sous-chaînes et sous-coupes
variables globales

Cet article fournit une explication détaillée de diverses fuites.

Avant de tirer des conclusions, procédons d'abord à un profilage.

Godebug

Divers outils de débogage peuvent être activés à l'aide d'une variable d'environnement GODEBUG, en passant une liste de paires séparées par des virgules name=value.

Planificateur de trace

La trace du planificateur peut fournir des informations sur le comportement de la goroutine au moment de l'exécution. Pour activer la trace du planificateur, exécutez le programme avec GODEBUG=schedtrace=100, la valeur détermine la période de sortie en 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 est la longueur de la file d'attente globale des goroutines à exécuter. Les nombres entre parenthèses correspondent à la longueur de la file d'attente de processus.

La situation idéale est lorsque tous les processus sont occupés à exécuter des goroutines et que la longueur modérée de la file d'attente d'exécution est uniformément répartie entre tous les processus:

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]

En regardant la sortie de schedtrace , nous pouvons voir des périodes de temps où presque tous les processus sont inactifs. Cela signifie que nous n'utilisons pas le processeur à pleine capacité.

Trace de ramasse-miettes

Pour activer le traçage de récupération de place (GC), exécutez le programme avec une variable d'environnement 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
.
.
.

Comme nous le voyons ici, la quantité de mémoire utilisée augmente et le temps nécessaire à gc pour terminer son travail augmente également. Cela signifie que nous consommons plus de mémoire qu'elle ne peut en gérer.

Vous GODEBUGpouvez en savoir plus sur et sur d' autres variables d'environnement golang ici .

Activation du profileur

go tool pprof- Un outil d'analyse et de profilage des données. Il existe deux façons de configurer pprof: runtime/pprofpar exemple pprof.StartCPUProfile(), appeler directement des fonctions dans votre code , ou installer un net/http/pproflisteur http et obtenir des données à partir de là, ce que nous avons fait. Il a une pproftrès faible consommation de ressources, il peut donc être utilisé en toute sécurité dans le développement, mais le point de terminaison du profil ne doit pas être accessible au public, car des données sensibles peuvent être divulguées.

Tout ce que nous devons faire pour la deuxième option est d'importer le package «net / http / pprof» :

import (
  _ "net/http/pprof"
)

puis ajoutez un listeur http:

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

Pprof a plusieurs profils par défaut:

allocs : récupère toutes les allocations de mémoire passées
block : trace de pile qui a conduit au blocage des primitives de synchronisation
goroutine : trace de pile de tous les goroutines actuels
tas : récupère les allocations de mémoire des objets vivants.
mutex : empiler la trace des détenteurs de mutex en conflit
profile : profil du processeur.
threadcreate : une trace de pile qui a conduit à la création de nouveaux threads dans l'OS
trace : trace l'exécution du programme en cours.

Remarque: le point de terminaison de trace, contrairement à tous les autres points de terminaison, est un profil de trace , pas pprof , vous pouvez le visualiser à l'aide de la trace de l'outil go go tool pprof.

Maintenant que tout est prêt, nous pouvons regarder les outils disponibles.

Profileur de processeur

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

Le profileur de processeur fonctionne par défaut pendant 30 secondes (nous pouvons changer cela en définissant le paramètre seconds) et collecte des échantillons toutes les 100 millisecondes, après quoi il passe en mode interactif. Les la plupart des commandes communes sont disponibles top, list, web.

Utilisez top npour afficher les entrées les plus chaudes au format texte, il existe également deux options pour trier la sortie, -cumpour l'ordre cumulatif et -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)

utiliser listpour explorer la fonction.

(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)

L'équipe webgénère un graphique SVG des zones critiques et l'ouvre dans le navigateur.

(pprof)web handleReques

Une grande quantité de temps passé dans les fonctions GC, telles que runtime.mallocgc, entraîne souvent une allocation de mémoire importante, ce qui peut ajouter de la charge au garbage collector et augmenter la latence.

Une grande partie du temps consacré aux mécanismes de synchronisation, tels que runtime.chansendou runtime.lock, peut être un signe de conflit.

Une grande quantité de temps consacré à syscall.Read/Writeune utilisation excessive des opérations d'E / S.

Profileur de mémoire

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

Par défaut, il affiche la durée de vie de la mémoire allouée. Nous pouvons voir le nombre d'objets sélectionnés en utilisant d' -alloc_objectsautres options utiles: -iuse_objectset -inuse_spacepour vérifier la mémoire en direct .

Habituellement, si vous voulez réduire la consommation de mémoire, vous devez regarder -inuse_space, mais si vous voulez réduire la latence, regardez -alloc_objectsaprès un temps d'exécution / de chargement suffisant.

Identification d'un goulot d'étranglement

Il est important de déterminer d'abord le type de goulot d'étranglement (processeur, E / S, mémoire) auquel nous sommes confrontés. En plus des profileurs, il existe un autre type d'outil.

go tool tracepeut montrer en détail ce que font les goroutins. Pour collecter un exemple de trace, nous devons envoyer une demande http au point de terminaison de trace:

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

Le fichier généré peut être visualisé à l'aide de l'outil de trace:

$ 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 est une application Web qui utilise le protocole Chrome DevTools et est compatible uniquement avec les navigateurs Chrome. La page principale ressemble à ceci:

Afficher la trace (0s-409.575266ms)
Afficher la trace (411.075559ms-747.252311ms)
Afficher la trace (747.252311ms-1.234968945s)
Afficher la trace (1.234968945s-1.774245108s)
Afficher la trace (1.774245484s-2.111339514s)
Voir la trace (2.111339514s-2.674030898s)
Voir la trace (2.674031362s-3.044145798s)
Voir la trace (3.044145798s-3.458795252s)
Voir la trace (3.43953778s-4.075080634s)
Voir la trace (4.075081098s-4.439271287s)
Voir la trace 4.4 (4.43927 -4.814869651s)
Voir trace (4.814869651s-5.253597835s) Profil de blocage du réseau d'

analyse Goroutine
()
Profil de blocage de synchronisation ()
Profil de blocage Syscall ()
Profil de latence du planificateur ()
Tâches définies par l'
utilisateur Régions définies par l'utilisateur Utilisation
minimale du mutateur Le

traçage divise le temps de trace afin que votre navigateur puisse le gérer.

Il y a une énorme quantité de données ici, ce qui les rend presque illisibles si nous ne savons pas ce que nous recherchons. Laissons-le pour l'instant.

Le lien suivant sur la page principale est «analyse de goroutine» , qui montre les différents types de goroutines de travail dans le programme pendant la période de trace:

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

Cliquez sur le premier élément avec N = 441703 , voici ce que nous obtenons:

analyse du goroutin

C'est très intéressant. La plupart des opérations ne prennent presque pas de temps à terminer et la plupart du temps est passé dans le bloc Sync. Examinons de plus près l'un d'eux:

motif de trace de goroutine

Il semble que notre programme soit presque toujours inactif. De là, nous pouvons aller directement à l'outil de verrouillage; le profilage des verrous est désactivé par défaut, nous devons d'abord l'activer dans notre code:

runtime.SetBlockProfileRate(1)

Maintenant, nous pouvons obtenir une sélection de serrures:

$ 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)

Nous avons ici deux verrous différents ( poll.fdMutex et sync.Mutex ), responsables de près de 100% des verrous. Cela confirme notre hypothèse sur un conflit de verrouillage, il ne nous reste plus qu'à trouver où cela se produit:

(pprof) svg lock

Cette commande crée un graphique vectoriel de tous les nœuds sensibles aux conflits en mettant l'accent sur les fonctions de blocage:

graphique svg du point de terminaison de blocage,

nous pouvons obtenir le même résultat du point de terminaison goroutine:

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

et alors:

(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)

presque tous nos programmes sont situés dans runtime.gopark, c'est un planificateur de go qui dort les goroutines; une raison très courante en est un conflit de verrouillage

(pprof) svg gopark

svg-graph of the endpoint goroutin

Ici, nous voyons deux sources de conflit:

UDPConn.WriteMsg ()

Il semble que toutes les réponses finissent par écrire dans le même FD (d'où le verrou), cela a du sens, car elles ont toutes la même adresse source.

Nous avons mené une petite expérience avec différentes solutions et finalement nous avons décidé d'utiliser plusieurs écouteurs pour équilibrer la charge. Ainsi, nous permettons au système d'exploitation d'équilibrer les demandes entrantes entre différentes connexions et de réduire les conflits.

Rand ()

Il semble qu'il y ait un verrou dans les fonctions mathématiques / rand régulières (plus d'informations ici ). Cela peut être facilement résolu à l'aide d' Rand.New()un générateur de nombres aléatoires qui crée un wrapper non bloquant.

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

C'est un peu mieux, mais créer une nouvelle source coûte cher à chaque fois. Est-il possible de faire encore mieux? Dans notre cas, nous n'avons vraiment pas besoin d'un nombre aléatoire. Nous avons juste besoin d'une distribution uniforme pour équilibrer la charge, et il s'avère que cela Time.Nanoseconds()peut nous convenir.

Maintenant que nous avons supprimé tous les verrous inutiles, regardons les résultats: l'

analyse de goroutin

semble meilleure, mais toujours, la plupart du temps il faut pour verrouiller la synchronisation. Jetons un coup d'œil au profil de verrouillage de synchronisation à partir de la page principale de l'interface utilisateur de trace:

chronologie du verrouillage de synchronisation

Jetons un coup d'œil à la fonction boost ccachedu point de terminaison du verrou 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:

Tous les appels se ccache.Get()terminent sur un canal c.promotables. La mise en cache est une partie importante de notre service, nous devons considérer d'autres options; Dans Dgraph a un excellent article sur l'état du cache! Go , ils ont également un excellent module de mise en cache appelé ristretto . Malheureusement, ristretto ne prend pas encore en charge la version basée sur Ttl, nous pouvons contourner ce problème en utilisant une très grande MaxCostet en conservant la valeur de délai d'attente dans notre structure de cache (nous voulons conserver les données obsolètes dans le cache). Voyons le résultat lors de l'utilisation de ristretto:

analyse du goroutin

Génial!

Nous avons pu réduire le temps d'exécution maximal de la gorutine de 5000 ms à 22 ms. Cependant, la majeure partie du temps d'exécution est divisée entre «verrouillage de synchronisation» et «attente de l'ordonnanceur». Voyons si nous pouvons y faire quelque chose: la

chronologie du verrou de synchronisation

Nous pouvons faire peu avec elle fdMutex.rwlock, concentrons-nous maintenant sur une autre: gcMarkDone, qui est responsable de 53% du temps de blocage. Cette fonctionnalité fait partie du processus de récupération de place. Leur présence dans la section critique est souvent un signe que nous surchargeons gc.

optimisation de l'allocation

À ce stade, il peut être utile de voir comment fonctionne le ramasse-miettes; Go utilise un sélecteur de marquage et de balayage. Il garde une trace de tout ce qui est sélectionné et dès qu'il atteint le double de la taille (ou de toute autre valeur définie par GOGC) de la taille de la taille précédente, le nettoyage du GC démarre. L'évaluation se déroule en trois étapes:

Réglage du marqueur (STW)
Marquage (parallèle)
Fin de l'étiquetage (STW)

Les phases Stop The World (STW) arrêtent l'ensemble du processus, bien qu'elles soient généralement très courtes, des cycles continus peuvent augmenter la durée. En effet, à l'heure actuelle (passez à la version 1.13), les goroutines ne sont supplantées qu'aux points de l'appel de fonction.Par conséquent, pour un cycle continu, un temps de pause arbitrairement long est possible, car le GC s'attend à ce que tous les goroutines s'arrêtent.

Pendant le marquage, gc utilise environ 25% GOMAXPROCS, mais des fonctions auxiliaires supplémentaires peuvent être ajoutées de force pour l' aide au marquage , cela se produit lorsque le goroutine se déplace rapidement sur le marqueur d'arrière-plan pour réduire le retard causé par gc, nous devons minimiser l'utilisation du tas.

Deux choses à noter:

le nombre d'allocations est plus important que la taille (par exemple, 1 000 allocations de mémoire à partir d'une structure de 20 octets créent beaucoup plus de charge sur le tas qu'une allocation unique de 20 000 octets);
contrairement aux langages comme C / C ++, toutes les allocations de mémoire ne se retrouvent pas sur le tas. Le compilateur go décide si la variable va se déplacer vers le tas ou si elle peut être placée à l'intérieur du cadre de pile. Contrairement aux variables allouées sur le tas, les variables allouées sur la pile ne chargent pas gc.

Pour plus d'informations sur le modèle de mémoire Go et l'architecture GC, consultez cette présentation .

Pour optimiser l'allocation de mémoire, nous utilisons la boîte à outils go:

profileur de processeur pour trouver des distributions à chaud;
profileur de mémoire pour le suivi des allocations;
traceur pour motifs; Gc
échapper à l'analyse pour découvrir pourquoi l'allocation a lieu.

Commençons par le profileur de processeur:

$ 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

Nous sommes particulièrement intéressés par les fonctions connexes, mallocgcc'est là que l'aide avec les balises

(pprof) svg mallocgc

Nous pouvons suivre la distribution à l'aide du point de terminaison alloc, l'option alloc_objectsignifie le nombre total d'allocations, il existe d'autres options pour utiliser la mémoire et l'espace d'allocation.

$ 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

À partir de maintenant, nous pouvons utiliser list pour chaque fonction et voir si nous pouvons réduire l'allocation de mémoire. Vérifions: les

fonctions de type printf

(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:

La ligne 41 est particulièrement intéressante, même lorsque le débogage est désactivé, la mémoire y est toujours allouée, nous pouvons utiliser l'analyse d'échappement pour l'examiner plus en détail.

L'outil d'analyse Go Escape est en fait un indicateur de compilation

$ go build -gcflags '-m'

Vous pouvez ajouter un autre -m pour plus d'informations.

$ go build -gcflags '-m '

pour une interface plus pratique, utilisez le fichier annoté par vue .

$ 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
.
.
.

Ici, tous les paramètres Debugfvont au tas. Cela est dû à la manière de déterminer Debugf:

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

Tous les paramètres sont argsconvertis en un type interface{}qui est toujours sauvegardé dans le tas. Nous pouvons soit supprimer les journaux de débogage, soit utiliser une bibliothèque de journaux avec une distribution nulle, par exemple, zerolog .

Pour plus d'informations sur l'analyse d'échappement, voir «eficiency d'allocation dans golang» .

Travailler avec des cordes

(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)

Puisqu'une ligne dans Go est immuable, la création d'une ligne temporaire provoque l'allocation de mémoire. À partir de Go 1.10, vous pouvez l'utiliser strings.Builderpour créer une chaîne.

(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()

Comme nous ne nous soucions pas de la valeur de la ligne inversée, nous pouvons l'éliminer Split()en retournant simplement la ligne entière.

(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")

En savoir plus sur l'utilisation des chaînes ici .

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) {

Nous utilisons les fonctions maxmiddb pour obtenir des données de géolocalisation. Ces fonctions sont considérées interface{}comme des paramètres qui, comme nous l'avons vu précédemment, peuvent provoquer des pousses de tas.

nous pouvons utiliser sync.Poolpour mettre en cache les éléments sélectionnés mais non utilisés pour une réutilisation ultérieure.

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
}

Plus d'informations sur sync.Pool ici .

Il existe de nombreuses autres optimisations possibles, mais pour le moment, il semble que nous en ayons déjà fait assez. Pour plus d'informations sur les techniques d'optimisation de la mémoire, vous pouvez lire Efficacité d'allocation dans les services Go hautes performances .

résultats

Afin de visualiser les résultats de l'optimisation de la mémoire, nous utilisons un diagramme go tool traceintitulé "Minimum Mutator Utilization", ici Mutator signifie not gc.

Avant l'optimisation:

Ici, nous avons une fenêtre d'environ 500 millisecondes sans utilisation efficace (gc consomme toutes les ressources), et nous n'obtiendrons jamais 80% d'utilisation efficace à long terme. Nous voulons que la fenêtre d'utilisation effective zéro soit aussi petite que possible, et aussi rapidement que possible pour atteindre 100% d'utilisation, quelque chose comme ceci:

après optimisation:

Conclusion

Grâce aux outils go, nous avons pu optimiser notre service pour gérer un grand nombre de demandes et une meilleure utilisation des ressources système.

Vous pouvez voir notre code source sur GitHub . Voici une version non optimisée et voici une version optimisée.

Il sera également utile

C'est tout. Rendez-vous sur le parcours !

Comment nous avons optimisé notre serveur DNS à l'aide des outils GO