Как мы оптимизировали наш DNS-сервер с помощью инструментов GO

В преддверии старта нового потока по курсу «Разработчик Golang» подготовили перевод интересного материала.

---

Наш авторитетный DNS-сервер используют десятки тысяч веб-сайтов. Мы ежедневно отвечаем на миллионы запросов. В наши дни DNS-атаки становятся все более и более распространенными, DNS является важной частью нашей системы, и мы должны убедиться, что мы можем хорошо работать под высокой нагрузкой.

dnsflood — это небольшой инструмент, способный генерировать огромное количество udp запросов.

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

Мониторинг систем показал, что использование памяти нашим сервисом росло так быстро, что нам пришлось остановить его, иначе мы столкнулись бы с OOM ошибками. Это было похоже на проблему утечки памяти; существуют различные причины «похожих на» и «реальных» утечек памяти в go:

• висящие горутины
• неправильное использование defer и finalizer
• подстроки и подсрезы
• глобальные переменные

Этот пост содержит подробное объяснение различных случаев утечек.

Прежде чем делать какие-либо выводы, давайте сначала проведем профилирование.

GODEBUG

Различные средства отладки можно включить с помощью переменной среды GODEBUG, передав список разделенных запятыми пар name=value.

Трассировка планировщика

Трассировка планировщика (scheduler trace) может предоставить информацию о поведении горутин во время выполнения. Чтобы включить трассировку планировщика, запустите программу с GODEBUG=schedtrace=100, значение определяет период вывода в мс.

$ 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 — это длина глобальной очереди запускаемых горутин. Числа в скобках — это длина очереди процессов.

Идеальная ситуация — когда все процессы заняты выполнением горутин, и умеренная длина очереди выполнения равномерно распределена между всеми процессами:

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]

Глядя на вывод schedtrace, мы можем видеть периоды времени, когда почти все процессы простаивают. Это означает, что мы не используем процессор на полную мощность.

Трассировка сборщика мусора

Чтобы включить трассировку сборщика мусора (GC), запустите программу с переменной среды 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
.
.
.

Как мы здесь видим, объем используемой памяти увеличивается, также увеличивается и количество времени, необходимое gc для выполнения своей работы. Это означает, что мы потребляем больше памяти, чем он может обработать.

Больше о GODEBUG и некоторых других переменных среды golang можно узнать здесь.

Включение профилировщика

go tool pprof — инструмент для анализа и профилирования данных. Есть два способа настроить pprof: либо напрямую вызывать функции runtime/pprof в вашем коде, например pprof.StartCPUProfile(), либо установить net/http/pprof http-листнер и получать оттуда данные, что мы и сделали. У pprof очень маленькое ресурсопотребление, поэтому его можно безопасно использовать в разработке, но эндпоинт профиля не должен быть публично доступен, поскольку могут быть раскрыты конфиденциальные данные.

Все, что нам нужно сделать для второго варианта, это импортировать пакет «net/http/pprof»:

import (
  _ "net/http/pprof"
)

затем добавить http-листнер:

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

У pprof есть несколько профилей по умолчанию:

• allocs: выборка всех прошлых распределений памяти
• block: трассировка стека, которая привела к блокировке примитивов синхронизации
• goroutine: трассировка стека всех текущих горутин
• heap: выборка выделений памяти живых объектов.
• mutex: трассировка стека держателей конфликтующих мьютексов
• profile: профиль процессора.
• threadcreate: трассировка стека, которая привела к созданию новых потоков в ОС
• trace: трассировка выполнения текущей программы.

Примечание: эндпоинт трассировки, в отличие от всех других эндпоинтов, является профилем трассировки, а не pprof, вы можете просмотреть его, используя go tool trace вместо go tool pprof.

Теперь, когда все подготовлено, мы можем посмотреть на доступные инструменты.

Профилировщик процессора

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

Профилировщик процессора по умолчанию работает в течение 30 секунд (мы можем изменить это, задав параметр seconds) и собирает выборки каждые 100 миллисекунд, после чего он переходит в интерактивный режим. Наиболее распространенными из доступных команд являются top, list, web.

Используйте top n для просмотра самых горячих записей в текстовом формате, также есть две опции для сортировки вывода, -cum для кумулятивного порядка и -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)

используйте list, чтобы исследовать функцию.

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

Команда web генерирует SVG-график критических участков и открывает его в браузере.

(pprof)web handleReques



Большое количество времени, проводимого в функциях GC, таких как runtime.mallocgc, часто приводит к значительному выделению памяти, что может добавить нагрузки на сборщик мусора и увеличить задержку.

Большое количество времени, затрачиваемое на механизмы синхронизации, такие как runtime.chansend или runtime.lock, может быть признаком конфликта.

Большое количество времени, затрачиваемое на syscall.Read/Write означает чрезмерное использование операций ввода-вывода.

Профилировщик памяти

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

По умолчанию он показывает время жизни выделенной памяти. Мы можем увидеть количество выделенных объектов, используя -alloc_objects, другие полезные опции: -iuse_objects и -inuse_space для проверки живой памяти.

Обычно, если вы хотите уменьшить потребление памяти, вам нужно посмотреть на -inuse_space, но если вы хотите уменьшить задержку, посмотрите на -alloc_objects после достаточного времени выполнения/загрузки.

Выявление узкого места

Важно сначала определить тип узкого места (процессор, ввод/вывод, память), с которым мы имеем дело. Помимо профилировщиков, есть еще один вид инструментов.

go tool trace может показать, что горутины делают в деталях. Чтобы собрать пример трассировки, нам нужно отправить http запрос на эндпоинт трассировки:

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

Сгенерированный файл можно просмотреть с помощью инструмента трассировки:

$ 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 — это веб-приложение, которое использует протокол Chrome DevTools и совместимо только с браузерами Chrome. Главная страница выглядит примерно так:

View trace (0s-409.575266ms)
View trace (411.075559ms-747.252311ms)
View trace (747.252311ms-1.234968945s)
View trace (1.234968945s-1.774245108s)
View trace (1.774245484s-2.111339514s)
View trace (2.111339514s-2.674030898s)
View trace (2.674031362s-3.044145798s)
View trace (3.044145798s-3.458795252s)
View trace (3.43953778s-4.075080634s)
View trace (4.075081098s-4.439271287s)
View trace (4.439271635s-4.814869651s)
View trace (4.814869651s-5.253597835s)

Goroutine analysis
Network blocking profile ()
Synchronization blocking profile ()
Syscall blocking profile ()
Scheduler latency profile ()
User-defined tasks
User-defined regions
Minimum mutator utilization

Трассировка разделяет время трассировки, чтобы ваш браузер мог справиться с этим



Здесь огромное множество данных, что делает их практически нечитаемыми, если мы не знаем что ищем. Давайте пока оставим это.

Следующая ссылка на главной странице — «goroutine analysis», который показывает различные виды работающих горутин в программе в течение периода трассировки:

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

Нажмите на первый элемент с N = 441703, вот что мы получим:


анализ горутин

Это очень интересно. Большинство операций практически не тратят времени на выполнение, а большую часть времени проводят в блоке Sync. Давайте подробнее рассмотрим одну из них:


схема трассировки горутин

Похоже, наша программа почти всегда неактивна. Отсюда мы можем перейти непосредственно к инструменту блокировки; профилирование блокировки по умолчанию отключено, нам нужно сначала включить его в нашем коде:

runtime.SetBlockProfileRate(1)

Теперь мы можем получить выборку блокировок:

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

Здесь у нас есть две разные блокировки (poll.fdMutex и sync.Mutex), отвечающие почти за 100% блокировок. Это подтверждает наше предположение о конфликте блокировок, теперь нам нужно только найти, где это происходит:

(pprof) svg lock

Эта команда создает векторный граф всех узлов, учитывающих конфликты, с упором на функции блокировки:


svg-график эндпонта блокировки

мы можем получить тот же результат из эндпоинта горутины:

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

и затем:

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

почти все наши программы находятся в runtime.gopark, это планировщик go, усыпляющий горутины; очень распространенная причина этого — конфликт блокировок

(pprof) svg gopark

svg-график конечной точки горутин

Здесь мы видим два источника конфликтов:

UDPConn.WriteMsg()

Похоже, что все ответы заканчиваются записью на один и тот же FD (отсюда и блокировка), это имеет смысл, поскольку все они имеют один и тот же адрес источника.

Мы провели небольшой эксперимент с различными решениями, и в конце решили использовать несколько листнеров для балансировки нагрузки. Таким образом, мы позволяем ОС балансировать входящие запросы между различными соединениями и уменьшать конфликты.

Rand()

Похоже, что в обычных math/rand функциях есть блокировка (подробнее об этом здесь). Это можно легко исправить с помощью Rand.New(), который создает генератор случайных чисел без блокировочной обертки

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

Это немного лучше, но создавать новый источник каждый раз дорого. Можно ли сделать еще лучше? В нашем случае нам действительно не нужно случайное число. Нам просто нужно равномерное распределение для балансировки нагрузки, и получается, что Time.Nanoseconds() может нам подойти.

Теперь, когда мы устранили все лишние блокировки, давайте посмотрим на результаты:


анализ горутин

Выглядит лучше, но все же большая часть времени уходит на блокировку синхронизации. Давайте посмотрим на профиль блокировки синхронизации с главной страницы пользовательского интерфейса трассировки:


график времени блокировки синхронизации

Давайте взглянем на функцию повышения ccache с конечной точки блокировки 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:

Все вызовы ccache.Get() заканчиваются отправкой на один канал c.promotables. Кэширование является важной частью нашего сервиса, мы должны рассмотреть другие варианты; У Dgraph есть отличная статья о состоянии кэша в go, у них также есть отличный модуль кэширования под названием ristretto. К сожалению, ristretto пока не поддерживает высвобождение на основе Ttl, мы могли бы обойти эту проблему, используя очень большой MaxCost и сохранив значение тайм-аута в нашей структуре кэша (мы хотим сохранить устаревшие данные в кэше). Давайте посмотрим результат при использовании ristretto:


анализ горутин

Отлично!

Нам удалось сократить максимальное время выполнения горутины с 5000 мс до 22 мс. Тем не менее, большая часть времени выполнения делится между «блокировкой синхронизации» и «ожиданием планировщика». Давайте посмотрим, сможем ли мы что-нибудь с этим сделать:


график времени блокировки синхронизации

Мы мало что можем сделать с fdMutex.rwlock, теперь давайте сосредоточимся на другом: gcMarkDone, который отвечает за 53% времени блока. Эта функция является частью процесса сбора мусора. Их наличие в критическом участке часто является признаком того, что мы перегружаем gc.

оптимизация аллокаций

На этом этапе может быть полезно посмотреть, как работает сборка мусора; Go использует mark-and-sweep сборщик. Он отслеживает все, что выделено, и как только он достигает в два раза большего (или любого другого значения, на которое установлено GOGC) размера от предыдущего размера, запускается очистка GC. Оценка происходит в три этапа:

• Установка маркера (STW)
• Маркировка (параллельно)
• Окончание маркировки (STW)

Фазы «Остановить мир» (Stop The World, STW) останавливают весь процесс, хотя они, как правило, очень короткие, сплошные циклы могут увеличить продолжительность. Это потому, что в настоящее время (go v1.13) горутины являются вытесняемыми только в точках вызова функции, поэтому для сплошного цикла возможно произвольно большое время паузы, поскольку GC ожидает остановки всех горутин.

Во время маркировки gc использует около 25% GOMAXPROCS, но дополнительные вспомогательные функции могут быть принудительно добавлены в mark assist, это происходит, когда быстро выделяющаяся горутина опережает фоновый маркер, чтобы уменьшить задержку, вызванную gc, нам нужно минимизировать использование кучи.

Следует отметить две вещи:

• количество выделений имеет большее значение, чем размер (например, 1000 выделений памяти из 20-байтовой структуры создают гораздо больше нагрузки на кучу, чем одно выделение 20000 байтов);
• в отличие от таких языков, как C/C++, не все выделения памяти оказываются в куче. Компилятор go решает, будет ли переменная перемещаться в кучу или она может быть размещена внутри фрейма стека. В отличие от переменных, размещаемых в куче, переменные, выделенные в стеке, не нагружают gc.

Для получения дополнительной информации о модели памяти Go и архитектуры GC смотрите эту презентацию.

для оптимизации выделения памяти мы используем набор инструментов go:

• профилировщик процессора, чтобы найти горячие распределения;
• профилировщик памяти для отслеживания выделений;
• трассировщик для паттернов; GC
• escape-анализ, чтобы выяснить, почему происходит аллокация.

Давайте начнем с профилировщика процессора:

$ 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

Нас особенно интересуют функции, связанные с mallocgc, именно здесь происходит помощь с метками

(pprof) svg mallocgc

Мы можем отслеживать распределение, используя конечную точку alloc, опция alloc_object означает общее количество аллокаций, есть и другие варианты использования памяти и пространства выделения.

$ 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

С этого момента мы можем использовать list для каждой функции и посмотреть, сможем ли мы уменьшить выделение памяти. Давайте проверим:

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:

Строка 41 особенно интересна, даже когда отладка отключена, там все еще выделяется память, мы можем использовать escape-анализ, чтобы исследовать ее подробнее.

Инструмент Escape-анализа Go на самом деле флаг компилятора

$ go build -gcflags '-m'

Вы можете добавить другой -m для получения дополнительной информации

$ go build -gcflags '-m '

для более удобного интерфейса используйте 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
.
.
.

Здесь все параметры Debugf уходят в кучу. Это происходит из-за способа определения Debugf:

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

Все параметры args преобразуются в тип interface{}, который всегда сбрасывается в кучу. Мы можем либо удалить журналы отладки, либо использовать библиотеку журналов с нулевым распределением, например, zerolog.

Для получения дополнительной информации об escape- анализе см. «allocation eficiency in golang».

Работа со строками

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

Поскольку строка в Go является неизменяемой, создание временной строки вызывает выделение памяти. Начиная с Go 1.10, можно использовать strings.Builder для создания строки.

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

Поскольку нас не волнует значение перевернутой строки, мы можем устранить Split(), просто перевернув всю строку.

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

Прочитать подробнее о работе со строками можно здесь.

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

Мы используем функции maxmiddb для получения данных геолокации. Эти функции принимают interface{} в качестве параметров, которые, как мы видели ранее, могут вызывать побеги кучи.

мы можем использовать sync.Pool для кэширования выделенных, но неиспользуемых элементов для последующего повторного использования.

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
}

Больше о sync.Pool здесь.

Есть много других возможных оптимизаций, но на данный момент, кажется, мы уже сделали достаточно. Для получения дополнительной информации о методах оптимизации памяти, можете прочитать Allocation efficiency in high-performance Go services.

Результаты

Чтобы визуализировать результаты оптимизации памяти, мы используем диаграмму в go tool trace под названием «Minimum Mutator Utilization», здесь Mutator означает не gc.

До оптимизации:



Здесь у нас есть окно около 500 миллисекунд без эффективного использования (gc потребляет все ресурсы), и мы никогда не получим 80% эффективного использования в долгосрочной перспективе. Мы хотим, чтобы окно нулевого эффективного использования было как можно меньше, и максимально быстро достигать 100% использования, как-то так:

после оптимизации:

Вывод

С помощью инструментов go нам удалось оптимизировать наш сервис для обработки большого количества запросов и лучшего использования системных ресурсов.

Вы можете посмотреть наш исходный код на GitHub. Вот неоптимизированная версия и вот оптимизированная.

Также будет полезно

• go perfbook
• effective go
• so you wanna go fast
• writing high performace go

На этом все. До встречи на курсе!