Профілювання та оптимізація програм на Go

Введення
У цій статті я розповім, як профілювати та оптимізувати програми на мові Go з використанням вбудованих і загальних інструментів, доступних в ОС Linux.

Що таке профайлинг і оптимізація? Якщо ваша програма працює недостатньо швидко, використовує занадто багато пам'яті, неоптимально використовує процесор, ви хочете зрозуміти, в чому справа, і виправити — це і є профайлинг і оптимізація.

Я навів таке визначення, щоб відразу відсікти питання некоректної роботи програми. У цій статті ми не будемо говорити про проблеми мультитредового програмування, про дата-рейсах (англ. data race), про пошук помилок (англ. debugging). Для всього цього в Go є свої утиліти і підходи, але залишимо цю тему на майбутнє.





Процесор
Почнемо сьогоднішній огляд з процесора.

В Go існує вбудований профайлер, зроблений за образом і подобою профайлера з набору утиліт gperftools для C/C++. Більш того, написаний на Go аналог утиліти pprof, призначеної для візуалізації результатів профілювання, став тепер основною версією і рекомендується для візуалізації як для Go, так і для C/C++.

Якщо говорити про класифікацію, то профайлер Go є «семплирующим» (англ. sampling profiler). Це означає, що з якоюсь періодичністю ми перериваємо роботу програми, беремо стек-трейс, записуємо його кудись, а в кінці, на основі того, як часто в стек-трейсах зустрічаються різні функції, ми розуміємо, які з них використовували більше ресурсів процесора, а які менше.

Практично всі утиліти і профайлери Go ми можемо запускати кількома способами, деякі з яких описані в цій статті.

Давайте почнемо з прикладу, а після поговоримо докладніше.

Приклад
package perftest

import (
"regexp"
"strings"
"testing"
)

var haystack = `Lorem ipsum dolor sit amet, consectetur adipiscing elit. Cras accumsan nisl et iaculis fringilla. Integer sapien orci, facilisis ut venenatis nec, suscipit at massa. Cras suscipit lectus non neque molestie, et imperdiet sem ultricies. Donec sit amet mattis nisi, efficitur posuere enim. Aliquam erat volutpat. Curabitur mattis nunc nisi, eu maximus dui facilisis in. Quisque vel tortor mauris. Praesent tellus sapien, vestibulum nec purus ut, luctus egestas odio. Ut ac ipsum non ipsum elementum pretium in id enim. Aenean eu augue fringilla, molestie orci et, tincidunt ipsum.
Nullam maximus odio vitae augue fermentum laoreet eget scelerisque ligula. Praesent pretium eu lacus in ornare. Maecenas fermentum id sapien non faucibus. Donec est tellus, auctor eu iaculis quis, accumsan vitae ligula. Fusce dolor nisl, pharetra eu facilisis non, hendrerit ac turpis. Pellentesque imperdiet aliquam quam in luctus. Curabitur ut orci sodales, faucibus nunc ac, maximus odio. Vivamus vitae nulla posuere, pellentesque quam posuere`

func BenchmarkSubstring(b *testing.B) {
for i := 0; i < b.N; i++ {
strings.Contains(haystack, "auctor")
}
}

func BenchmarkRegex(b *testing.B) {
for i := 0; i < b.N; i++ {
regexp.MatchString("auctor", haystack)
}
}

Перед вами два бенчмарку, кожен з яких N раз робить пошук підрядка в рядку. Один робить це з використанням пакету регулярних виразів, а інший — з використанням пакету strings. Шукаємо слово auctor.

Запустимо бенчмарк і подивимося на результати.

$ go test bench=.
testing: warning: no to run tests
BenchmarkSubstring-8 10000000 194 ns/op
BenchmarkRegex-8 200000 7516 ns/op
PASS
ok github.com/mkevac/perftest00 3.789 s

Результат очікуваний, оскільки регулярні вирази — набагато більш потужний і тому повільний інструмент, але давайте спробуємо отпрофилировать цей код.

Найпростіший спосіб скористатися профайлером в даному випадку — запустити той самий бенчмарк з додатковим параметром -cpuprofile cpu.out. В результаті в каталозі з'явиться файл cpu.out з результатами профілювання і бінарники, який необхідний для отримання символів, дизассемблирования і т. д.

Бінарники насправді створюється завжди, але в звичайному випадку він створюється в тимчасовій директорії і віддаляється відразу після виконання бенчмарка. У разі запуску з профілюванням результуючий бінарники не видаляється.

Отже, запустимо бенчмарк BenchmarkRegex з профілюванням:

$ GOGC=off go test bench=BenchmarkRegex -cpuprofile cpu.out
testing: warning: no to run tests
BenchmarkRegex-8 200000 6773 ns/op
PASS
ok github.com/mkevac/perftest00 1.491 s

Як ви бачите, я запустив бенчмарк з префіксом GOGC=off. Змінна оточення GOGC, виставлена в off відключає garbage collector. Я це зробив свідомо, щоб garbage collector і його стек-трейсы не відволікали нас від ходу моєї розповіді.

До речі, відключення GC для недовго живуть скриптів і програм — відмінне рішення, яке може зменшити час роботи програми в рази. І не тільки в Go. Для PHP ми теж іноді використовуємо цей «фінт», наскільки я знаю. По суті, ми зменшуємо час роботи за рахунок використовуваної пам'яті на сервері.

Скористаємося тепер утилітою pprof, щоб візуалізувати граф викликів.

$ go tool pprof perftest00.test cpu.out

Найпростішим способом отримати граф є команда web, яка автоматично зберігає SVG-зображення у тимчасову директорію і запускає браузер, щоб її показати.

Якщо ви працюєте на віддаленому сервері, то цей варіант не пройде. Вам потрібно або прокинути X-сервер, використовуючи ключ -Y для SSH, або зберегти SVG-файл на диск командою go tool pprof -svg ./perftest00.test ./cpu.out > cpu.svg, скопіювати його до себе на комп'ютер і там відкрити.

У разі OSX, як у мене, вам потрібно буде встановити X сервер XQuartz, щоб прокидывание через SSH спрацювало.

Подивимося на отриманий граф викликів.



Вивчаючи такий граф, в першу чергу потрібно звертати увагу на товщину ребер (стрілок) і на розмір вузлів графа (квадратиків). На ребрах підписано час: скільки часу даний сайт або будь-який з нижче лежачих вузлів перебував у стек-трейсе під час профілювання.

Давайте підемо по жирним стрілках з самого першого (верхнього) вузла і дійдемо до першої розвилки.



Ми бачимо нашу функцію BenchmarkRegex, бачимо функцію regexp.MatchString, яку ми викликаємо, і бачимо, що вона роздвоюється.

Якщо ви коли-небудь використовували регулярні вирази, то ви, швидше за все, знаєте, що більшість реалізацій розділяє процес на етап компіляції початкового рядка подання регулярного виразу в якийсь проміжний варіант і на власне використання цього проміжного варіанту.

Напрошується тривіальна оптимізація: робити компіляцію один раз, а не багаторазово.

Зробимо це:

package perftest

import (
"regexp"
"strings"
"testing"
)

var haystack = `Lorem ipsum dolor sit amet, consectetur adipiscing 
[...]
Vivamus vitae nulla posuere, pellentesque quam posuere`
var pattern = regexp.MustCompile("auctor")

func BenchmarkSubstring(b *testing.B) {
for i := 0; i < b.N; i++ {
strings.Contains(haystack, "auctor")
}
}

func BenchmarkRegex(b *testing.B) {
for i := 0; i < b.N; i++ {
pattern.MatchString(haystack)
}
}

І подивимося, що змінилося:

$ go test bench=.
testing: warning: no to run tests
BenchmarkSubstring-8 10000000 170 ns/op
BenchmarkRegex-8 5000000 297 ns/op
PASS
ok github.com/mkevac/perftest01 3.685 s

Як видно, варіант з регулярними виразами прискорився на порядок і впритул наблизився до варіанту з простим пошуком підрядка.

А як же змінився граф викликів? Він став «сильно простіше», оскільки тепер компіляція робиться тільки один раз. Більш того, виклик компіляції взагалі не потрапив в граф, т. к. профілювання є семплирующим.



Відмінно. Давайте подивимося, які ще способи у нас є, для того щоб запускати Go-профілювальник CPU.

Способи запуску профайлера
Один із способів ми вже побачили — це параметр -cpuprofile для команди go test.

Ми також можемо запускати профайлер вручну, використовуючи функції pprof.StartCPUProfile() pprof.StopCPUProfile(). Трохи простіше скористатися зручною обгорткою над цими функціями від Дейва Чейні (англ. Dave Cheney) (https://github.com/pkg/profile), яка створить за вас файл, буде писати у нього і т. п.

І ще одним чудовим методом є використання пакету net/http/pprof. Якщо ви імпортуєте його, то він автоматично додасть HTTP-обробник для URL /debug/pprof, і ви зможете профілювати працюючу програму віддалено, використовуючи той же самий go tool pprof. Давайте подивимося, як це виглядає.

Напишемо простенький приклад:

package main

import (
"net/http"
_ "net/http/pprof"
)

func cpuhogger() {
var acc uint64
for {
acc += 1
if acc&1 == 0 {
acc <<= 1
}
}
}

func main() {
go http.ListenAndServe("0.0.0.0:8080", nil)
cpuhogger()
}

Як видно, ми імпортували пакет net/http/pprof і запустили HTTP-сервер командою http.ListenAndServe(). Цього достатньо, щоб використовувати профайлер під час роботи програми.

Давайте тепер запустимо програму і скористаємося профайлером:

$ go tool pprof http://localhost:8080/debug/pprof/profile?seconds=5

Як видно, ми просто передаємо утиліті pprof шлях до хендлеру, за яким «слухає» профайлер. Додатково можна передати час роботи профайлера (за замовчуванням 30 секунд).

Команда web працює відмінно, команда top працює відмінно, але ось list і disasm кажуть, що немає інформації про вихідні коди програми:

(pprof) web
(pprof) top
4.99 s of 4.99 s total ( 100%)
flat flat% sum% cum cum%
4.99 s 100% 100% 4.99 s 100% main.cpuhogger
0 0% 100% 4.99 s 100% runtime.goexit
0 0% 100% 4.99 s 100% runtime.main
(pprof) list cpuhogger
Total: 4.99 s
No source information for main.cpuhogger

Щоб отримати інформацію про вихідні коди, нам потрібно запустити pprof трохи інакше. Потрібно передати йому і шлях до бинарнику:

$ go tool pprof pproftest http://localhost:8080/debug/pprof/profile?seconds=5

Тепер ми можемо скористатися і list, і disasm і переконатися, що реальність співпадає з очікуваннями.

(pprof) list cpuhogger
Total: 4.97 s
ROUTINE ======================== main.cpuhogger in /home/marko/goprojects/src/github.com/mkevac/pproftest/main.go
4.97 s 4.97 s (flat, cum) 100% of Total
. . 6:)
. . 7:
. . 8:func cpuhogger() {
. . 9: var acc uint64
. . 10: for {
2.29 s 2.29 s 11: acc += 1
1.14 s 1.14 s 12: if acc&1 == 0 {
1.54 s 1.54 s 13: acc <<= 1
. . 14: }
. . 15: }
. . 16:}
. . 17:
. . 18:func main() {


(pprof) disasm cpuhogger
Total: 4.97 s
ROUTINE ======================== main.cpuhogger
4.97 s 4.97 s (flat, cum) 100% of Total
. . 401000: XORL AX, AX
1.75 s 1.75 s 401002: INCQ AX
1.14 s 1.14 s 401005: TESTQ $0x1, AX
. . 40100b: JNE 0x401002
1.54 s 1.54 s 40100d: SHLQ $0x1, AX
540ms 540ms 401010: JMP 0x401002
. . 401012: INT $0x3

Давайте заради інтересу копнемо глибше. Ми выкачаем те, що повертає URL самостійно:

$ curl http://localhost:8080/debug/pprof/profile?seconds=5 -o /tmp/cpu.log

Ми бачимо, що всередині /tmp/cpu.log такі ж двійкові дані, які повертаються при використанні go test tool -cpuprofile або StartCPUProfile(). «Натравим» команду strings на цей бінарний файл і зрозуміємо, що всередині немає назв функцій або так званих символів.

$ strings /tmp/cpu.log | grep cpuhogger

Звідки ж тоді в першому випадку, коли ми запускали pprof без бінарника, були отримані імена функцій? Виявляється, при імпорті net/http/pprof додається ще один URL /debug/pprof/symbol, який за адресою функції повертає її назву. З допомогою запитів до цього URL команда pprof отримує імена функцій.

Але цей URL не повертає ні вихідний код функції, ні дизасемблированный. Для дизасемблирования нам потрібен бінарники, а для вихідного коду нам потрібен і бінарники, і власне вихідний код на диску.

Будьте уважні: передаваний бінарники і вихідний код повинні бути саме ті, які запущені. Інакше ви можете отримати зовсім не ті дані, які очікуєте, і будете шукати проблеми там, де їх немає.

Як працює pprof?
Давайте уважно подивимося, як саме працює pprof і які недоліки має використовуваний підхід.

Для того щоб забезпечити роботу багатьох програм одночасно, сучасні десктопні і серверні операційні системи реалізують так звану що витісняє багатозадачність. Програмі виділяється певний часовий проміжок і певний процесор, на якому вона працює. Після закінчення цього часу ОС витісняє програму і запускає на її місці іншу, якщо вона готова до роботи.

Але як саме реалізована можливість переривання? Адже ОС — майже така ж програма. Вся справа в тому, що ОС просить залізо посилати їй сигнал з певною періодичністю і призначає на цей сигнал обробник. Коли сигнал приходить, процесор зупиняє все, що в даний момент працює на ньому, і запускає заданий обробник. У цьому процесорі ОС може витіснити або не витіснити поточний процес, замінити його іншим і т. д.

За таким же принципом працює і профайлер Go. Go runtime просить ОС посилати сигнал (man setitimer) з певною періодичністю і призначає на цей сигнал обробник. Обробник бере стек-трейс всіх горутин (англ. goroutines), якусь додаткову інформацію, записує її в буфер і виходить.

Саме з батогом у процесі доставки сигналів певним тредам і пов'язана проблема з попередніми версіями OS X.

Які ж недоліки даного підходу?

  • Кожен сигнал — це зміна контексту. Річ досить витратна у наш час. Тому на поточний момент реалістично отримати не більше 500 сигналів в секунду. Стандартне значення в Go зараз — 100 в секунду. Іноді цього замало.
  • Для нестандартних збірок, наприклад, з використанням -buildmode=c-archive або -buildmode=c-shared, профайлер працювати за замовчуванням не буде. Це пов'язано з тим, що сигнал SIGPROF, який посилає ОС, прийде в основний потік програми, який не контролюється Go.
  • Процес user space, яким є програма Go, не може отримати ядерну стек-трейс. Неоптимальності та проблеми іноді криються і в ядрі.
Основна перевага, звичайно, в тому, що Go runtime володіє повною інформацією про своєму внутрішньому устрої. Зовнішні засоби, наприклад, за замовчуванням нічого не знають про горутинах. Для них існують тільки процеси і треди.

Системні профайлери
Ми подивилися, як працює вбудований профайлер Go. Давайте подивимося, наскільки застосовні стандартні Linux-профайлери perf і SystemTap.

Візьмемо саму першу програму з статті, тільки перетворимо її з бенчмарків в звичайну програму, працюючу нескінченно.

package main

import (
"regexp"
"strings"
)

var haystack = `Lorem ipsum dolor sit amet, consectetur adipiscing [...]
Vivamus vitae nulla posuere, pellentesque quam posuere`

func UsingSubstring() bool {
found := strings.Contains(haystack, "auctor")
return found
}

func UsingRegex() bool {
found, _ := regexp.MatchString("auctor", haystack)
return found
}

func main() {
go func() {
for {
UsingSubstring()
}
}()

for {
UsingRegex()
}
}

SystemTap

SystemTap — дуже потужний профайлер, який дозволяє писати невеликі програмки на псевдоязыке. Ця програмка надалі автоматично перетворюється З збирається у вигляді ядерного модуля Linux, вантажиться, працює і вивантажується.

Подивимося, чи бачить SystemTap наші функції:

$ stap -l 'process("systemtap").function("main.*")'
process("systemtap").function("main.UsingRegex@main.go:16")
process("systemtap").function("main.UsingSubstring@main.go:11")
process("systemtap").function("main.init@main.go:32")
process("systemtap").function("main.main.func1@main.go:22")
process("systemtap").function("main.main@main.go:21")

Бачить. Всі наші функції мають префікс main, як і очікується.

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

Напишемо такий простий скрипт на SystemTap-мовою. Він запам'ятовує час на вході у функцію, заміряє час на виході, обчислює різницю і зберігає її. Після завершення роботи він цю інформацію друкує.

global etime
global intervals

probe $1.call {
etime = gettimeofday_ns()
}

probe $1.return {
intervals <<< (gettimeofday_ns() - etime)/1000
}

probe end {
printf("Duration min:%dus avg:%dus max:%dus count:%d\n",
@min(intervals), @avg(intervals), @max(intervals),
@count(intervals))
printf("Duration (us):\n")
print(@hist_log(intervals));
printf("\n")
}

Запустимо програму в одному терміналі і stap — в іншому.

$ sudo stap main.stap 'process("systemtap").function("main.UsingSubstring")'
^CDuration min:0us avg:1us max:586us count:1628362
Duration (us):
value|-------------------------------------------------- count
0 | 10
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1443040
2 | @@@@@ 173089
4 | 6982
8 | 4321
16 | 631
32 | 197
64 | 74
128 | 13
256 | 4
512 | 1
1024 | 0
2048 | 0

Ми отримали результат, але програма при цьому впала з помилкою, пропрацювавши зовсім трохи.

$ ./systemtap
runtime: unexpected return pc for main.UsingSubstring called from 0x7fffffffe000
fatal error: unknown caller pc

runtime stack:
runtime.throw(0x494e40, 0x11)
/home/marko/go/src/runtime/panic.go:566 +0x8b
runtime.gentraceback(0xffffffffffffffff, 0xc8200337a8, 0x0, 0xc820001d40, 0x0, 0x0, 0x7fffffff, 0x7fff2fa88030, 0x0, 0x0, ...)
/home/marko/go/src/runtime/traceback.go:311 +0x138c
runtime.scanstack(0xc820001d40)
/home/marko/go/src/runtime/mgcmark.go:755 +0x249
runtime.scang(0xc820001d40)
/home/marko/go/src/runtime/proc.go:836 +0x132
runtime.markroot.func1()
/home/marko/go/src/runtime/mgcmark.go:234 +0x55
runtime.systemstack(0x4e4f00)
/home/marko/go/src/runtime/asm_amd64.s:298 +0x79
runtime.mstart()
/home/marko/go/src/runtime/proc.go:1087

Я знайшов гілку про це на go-nuts, і рішення поки немає. Судячи з усього, те, як SystemTap змінює код програми, щоб перехоплювати функції, не подобається Go runtime при отриманні стек-трейса в GC.

Така ж проблема є і в C++ при обробці винятків. Uretprobes не ідеальна.

Добре, але виходить, що якщо не використовувати .return пробу, то все в порядку? Спробуємо.

Ось програма, яка бере випадкові числа, перетворює їх в рядок і кладе в буфер:

package main

import (
"bytes"
"fmt"
"math/rand"
"time"
)

func ToString(int number) string {
return fmt.Sprintf("%d", number)
}

func main() {
r := rand.New(rand.NewSource(time.Now().UnixNano()))
var buf bytes.Buffer
for i := 0; i < 1000; i++ {
value := r.Int() % 1000
value = value - 500
buf.WriteString(ToString(value))
}
}

Напишемо скриптик, який будує розподіл чисел, які ми перетворюємо в рядок.

global intervals

probe process("systemtap02").function("main.ToString").call {
intervals <<< $number
}

probe end {
printf("Variables min:%dus avg:%dus max:%dus count:%d\n",
@min(intervals), @avg(intervals), @max(intervals),
@count(intervals))
printf("Variables:\n")
print(@hist_log(intervals));
printf("\n")
}

Програма, на відміну від попередньої, не використовує .return-пробу, але зате бере і використовує аргумент number.

Запустимо і подивимося, що вийшло:

$ sudo stap main.stap -c ./systemtap02
Variables min:-499us avg:8us max:497us count:1000
Variables:
value|-------------------------------------------------- count
-1024 | 0
-512 | 0
-256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 249
-128 |@@@@@@@@@@@@@@@@@@@@ 121
-64 |@@@@@@@@@@ 60
-32 | @@@@@@ 36
-16 |@@ 12
-8 |@ 8
-4 | 5
-2 | 3
-1 | 2
0 | 2
1 | 2
2 | 3
4 |@ 7
8 | 4
16 |@@@ 20
32 | @@@@@ 33
64 |@@@@@@@ 44
128 |@@@@@@@@@@@@@@@@@@ 110
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 279
512 | 0
1024 | 0

У нас вийшов гарний графік з розподілом.

Perf

Утиліта perf і підсистема perf_events є на даний момент профайлером за замовчуванням в Linux. Вихідні коди і розробка проходять в основному репозиторії ядра і йдуть врівень з ядром.

perf top — команда, яка, аналогічно top, в реальному часі показує самий «гарячий» код. Запустимо нашу тестову програму і подивимося, що покаже perf top.

$ sudo perf top -p $(pidof systemtap)




Схоже, все відмінно, і навіть працюють анотації з вихідним і машинним кодом.



Тепер спробуємо побудувати так званий FlameGraph, який був популяризован Бренданом Греггом (англ. Brendan Gregg). Брендан зараз працює Netflix і є одним з основних популяризаторів і «двигуном» інновацій у сфері профілювання для Linux.

Знову ж таки, запустимо програму і зберемо стек-трейсы за 10 секунд в файл:

$ sudo perf record -F 99 -g -p $(pidof systemtap) -- sleep 10
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.149 MB perf.data (1719 samples) ]

Скористаємося утилітами від Брендана для перетворення даних perf в FlameGraph.

$ sudo perf script | ~/tmp/FlameGraph/stackcollapse-perf.pl > out.perf-folded
$ ~/tmp/FlameGraph/flamegraph.pl out.perf-folded > perf-kernel.svg

І ось що у нас вийшло:



Як видно, на відміну від вбудованого в Go профайлера, тут у нас є і стек-трейс ядра.

Пам'ять
Якщо б ми програмували на С або С++, як би ми профилировали використання пам'яті?

У світі С/C++ є Valgrind — утиліта, яка призначена для пошуку помилок при використанні пам'яті: витік, вихід за кордон масиву, використання вже звільненої пам'яті і багато ще чого. Все це нам не потрібно, оскільки в Go відсутність таких проблем гарантовано (крім випадку використання cgo, звичайно).

Але Valgrind ще і вміє показувати споживання пам'яті у вигляді зручного тимчасового графіка з допомогою вбудованої підсистеми Massif.

Якщо взяти простеньку програму, яка просто виділяє, а потім звільняє 20 MiB пам'яті

#include <stdlib.h>
#include <unistd.h>
#include < string.h>

int main() {
const size_t МБ = 1024*1024;
const unsigned count = 20;
char **buf = calloc(count, sizeof(*buf));

for (unsigned i = 0; i < count; i++) {
buf[i] = calloc(1, МБ);
memset(buf[i], 0xFF, МБ);
sleep(1);
}

for (unsigned i = 0; i < count; i++) {
free(buf[i]);
sleep(1);
}

free(buf);
}

і запустити її під Massif, то ми отримаємо приблизно такий графік з стек-трейсами в тих місцях, де були ініційовані виділення пам'яті:

--------------------------------------------------------------------------------
Command: ./main
Massif arguments: --pages-as-heap=yes --time-unit=ms
ms_print arguments: massif.out.15091
--------------------------------------------------------------------------------


MB
26.20^ ::
| ::: #
| @@: : #::
| ::@ : : #: ::
| ::::: @ : : #: : ::::
| :: : : @ : : #: : : : ::
| :::: : : @ : : #: : : : : :
| ::::: :: : : @ : : #: : : : : :::::
| ::: : : :: : : @ : : #: : : : : :: : @@
| ::: : : : :: : : @ : : #: : : : : :: : @ ::
| ::@: : : : : :: : : @ : : #: : : : : :: : @ : :::
| ::: @: : : : : :: : : @ : : #: : : : : :: : @ : : :::
| ::: : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: ::
| ::: : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : ::
| ::::: : : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : : ::::
|:: : : : : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : : : : :
|@: : : : : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : : : : :@
|@: : : : : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : : : : :@
|@: : : : : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : : : : :@
|@: : : : : : @: : : : : :: : : @ : : #: : : : : :: : @ : : :: : : : : :@
0 +----------------------------------------------------------------------->s
0 39.13

Number of snapshots: 66
Detailed snapshots: [9, 10, 20, 22, 32, 42, 45 (peak), 55, 65]

Працює Massif таким чином, що перевизначає основні функції для роботи з пам'яттю (malloc, calloc, realloc, memalign, new, new[]) на свої.

Go ж не використовує ні одну з цих функцій. В исходниках Go реалізований власний аллокатор, який запитує пам'ять безпосередньо в ОС з допомогою системних викликів mmap або sbrk, і вже її розбиває самостійно на більш дрібні шматочки.



Valgrind вміє ловити mmap/sbrk, якщо його попросити спеціальним параметром командного рядка, але це все одно марно, оскільки, по-перше, ми не побачимо ці більш дрібні виділення і звільнення і, по-друге, ми не зможемо зрозуміти, до якої пам'яті вже немає посилань, а яка все ще «жива».

Інші поширені утиліти в світі С/C++ теж практично марні, оскільки більшість з них працює аналогічним чином, тобто шляхом перехоплення функцій виділення та звільнення пам'яті.

Варіанти, по суті, два:
  • теоретично ми можемо перехоплювати функції виділення і звільнення пам'яті з Go runtime чимось зовнішнім по відношенню до Go-програмі (наприклад, перфорація або SystemTap) і спробувати щось зрозуміти на основі цих викликів;
  • використовувати вбудований в Go runtime-облік використання пам'яті.


Go вміє збирати інформацію про виділення пам'яті з певною періодичністю. Цю періодичність можна задавати вручну, але за замовчанням вона становить 1 раз на 512 кілобайт виділеної пам'яті.

Як зазвичай, давайте подивимося на приклад.

Приклад
Аналогічно процесорного профілізації, профілювання пам'яті можна запускати, використовуючи go test, прямі виклики runtime.MemProfile() або за допомогою пакету net/http/pprof. В цей раз давайте скористаємося останнім варіантом.

Отже, перед вами програма, яка в одній з горутин постійно виділяє масиви і зберігає їх в іншому масиві, а в іншій горутине робить те ж саме, але періодично «забуває» про масив масивів:

package main

import (
"net/http"
_ "net/http/pprof"
"time"
)

func allocAndKeep() {
var b [][]byte
for {
b = append(b, make([]byte, 1024))
time.Sleep(time.Millisecond)
}
}

func allocAndLeave() {
var b [][]byte
for {
b = append(b, make([]byte, 1024))
if len(b) == 20 {
b = nil
}
time.Sleep(time.Millisecond)
}
}

func main() {
go allocAndKeep()
go allocAndLeave()
http.ListenAndServe("0.0.0.0:8080", nil)
}

Тобто ми очікуємо, що одна з функцій викликає постійне зростання споживання пам'яті, а інша постійно генерує сміття для складальника, але зростання не викликає.

Давайте подивимося, що говорить профайлер.

У разі профілювання пам'яті для go tool pprof є чотири основних параметри, про які потрібно знати:
  • alloc_space — кількість аллоцированных байт;
  • alloc_objects — кількість аллоцированных об'єктів;
  • inuse_space — кількість живих байт;
  • inuse_objects — кількість живих об'єктів.


Перші два показують кількість всіх аллокаций в байтах та об'єктах, а другі — тільки кількість живих аллокаций в поточний момент.

В даному випадку ми очікуємо, що inuse покаже тільки функцію allocAndKeep(), alloc покаже обидві функції:

$ go tool pprof -inuse_space memtest http://localhost:8080/debug/pprof/heap
Fetching profile from http://localhost:8080/debug/pprof/heap
Saved profile in /home/marko/pprof/pprof.memtest.localhost:8080.inuse_objects.inuse_space.005.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
15.36 MB of 15.36 MB total ( 100%)
Dropped 2 nodes (cum <= 0.08 МБ)
flat flat% sum% cum cum%
15.36 MB 100% 100% 15.36 MB 100% main.allocAndKeep
0 0% 100% 15.36 MB 100% runtime.goexit


$ go tool pprof -alloc_space memtest http://localhost:8080/debug/pprof/heap
Fetching profile from http://localhost:8080/debug/pprof/heap
Saved profile in /home/marko/pprof/pprof.memtest.localhost:8080.alloc_objects.alloc_space.008.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
54.49 MB of 54.49 MB total ( 100%)
Dropped 8 nodes (cum <= 0.27 МБ)
flat flat% sum% cum cum%
27.97 MB 51.33% 51.33% 29.47 MB 54.08% main.allocAndKeep
23.52 MB 43.17% 94.49% 25.02 MB 45.92% main.allocAndLeave
3MB 5.51% 100% 3MB 5.51% time.Sleep
0 0% 100% 54.49 MB 100% runtime.goexit

Схоже на правду. Але ми також бачимо, що наш Sleep() чомусь теж виділяє пам'ять. Розглянемо докладніше.

(pprof) list time.Sleep
Total: 54.49 MB
ROUTINE ======================== time.Sleep in /home/marko/go/src/runtime/time.go
3MB 3MB (flat, cum) 5.51% of Total
. . 48:func timeSleep(ns int64) {
. . 49: if ns <= 0 {
. . 50: return
. . 51: }
. . 52:
3MB 3MB 53: t := new(timer)
. . 54: t.when = nanotime() + ns
. . 55: t.f = goroutineReady
. . 56: t.arg = getg()
. . 57: lock(&timers.lock)
. . 58: addtimerLocked(t)

Та, як виявилося, вбудована функція time.Sleep() явно виділяє пам'ять командою new().

Неявне виділення (1)
Начебто все просто у випадку, коли явно видно, що ось воно — виділення пам'яті. Але давайте розглянемо кілька прикладів, коли виділення не зовсім очевидно.

Візьмемо простенький приклад, де ми заповнюємо буфер рядками.

package printtest

import (
"bytes"
"fmt"
"testing"
)

func BenchmarkPrint(b *testing.B) {
var buf bytes.Buffer
var s string = "test string"
for i := 0; i < b.N; i++ {
buf.Reset()
fmt.Fprintf(&buf, "string is: %s", s)
}
}

У даному прикладі ми заповнюємо буфер за допомогою функції fmt.Fprintf().
Бенчмарк з параметром -benchmem говорить утиліті test виводити в тому числі і кількість аллокаций.

$ go test bench=. -benchmem
testing: warning: no to run tests
BenchmarkPrint-8 10000000 128 ns/op 16 B/op 1 allocs/op
PASS
ok github.com/mkevac/converttest 1.420 s

Отже, у нас 1 алокація на операцію розміром у 16 байт. Що це за алокація?

Запустимо профайлер наступною командою:

$ go test bench=. -memprofile=mem.out -memprofilerate=1

Тут memprofilerate задає частоту, з якою програма буде зберігати інформацію про аллокациях. Одиниця в даному випадку говорить про те, що треба зберігати всі до єдиної алокації. Зрозуміло, в продакшені така частота буде згубною для продуктивності. Але зараз можна.

Подивимося на виділення наступною командою:

$ go tool pprof -alloc_space converttest.test mem.out

(pprof) top
15.41 MB of 15.48 MB total (99.59%)
Dropped 73 nodes (cum <= 0.08 МБ)
flat flat% sum% cum cum%
15.41 MB 99.59% 99.59% 15.43 MB 99.67% github.com/mkevac/converttest.BenchmarkPrint
0 0% 99.59% 15.47 MB 99.93% runtime.goexit
0 0% 99.59% 15.42 MB 99.66% testing.(*B).launch
0 0% 99.59% 15.43 MB 99.67% testing.(*B).runN

Так, наша функція виділила в сумі 15 MiB пам'яті. Де?

(pprof) list BenchmarkPrint
Total: 15.48 MB
ROUTINE ======================== github.com/mkevac/converttest.BenchmarkPrint in /home/marko/goprojects/src/github.com/mkevac/converttest/convert_test.go
15.41 MB 15.43 MB (flat, cum) 99.67% of Total
. . 9:func BenchmarkPrint(b *testing.B) {
. . 10: var buf bytes.Buffer
. . 11: var s string = "test string"
. . 12: for i := 0; i < b.N; i++ {
. . 13: buf.Reset()
15.41 MB 15.43 MB 14: fmt.Fprintf(&buf, "string is: %s", s)
. . 15: }
. . 16:}

Все сталося у функції fmt.Fprintf(). Добре. А де?

(pprof) list fmt.Fprintf
Total: 15.48 MB
ROUTINE ======================== fmt.Fprintf in /home/marko/go/src/fmt/print.go
0 12.02 kB (flat, cum) 0.076% of Total
. . 175:// These routines end in 'f' and take a format string.
. . 176:
. . 177:// Fprintf formats according to a format specifier and writes to w.
. . 178:// It returns the number of bytes written and any write error encountered.
. . 179:func Fprintf(w io.Writer, format string, a ...interface{}) (int n, err error) {
. 11.55 kB 180: p := newPrinter()
. 480B 181: p.doPrintf(format a)
. . 182: n, err = w.Write(p.buf)
. . 183: p.free()
. . 184: return
. . 185:}
. . 186:

Ось де. А, ні, стривайте… Що-то з цифрами не те. До цього ми бачили 15 мегабайт, а тут 12 кілобайт. Щось не сходиться.

Подивимося на нашу функцію в дизасемблированном вигляді:

. . 466edb: CALL bytes.(*Buffer).Reset(SB)
. . 466ee0: LEAQ 0x98b6b(IP), AX
. . 466ee7: MOVQ AX, 0x70(SP)
. . 466eec: MOVQ $0xb, 0x78(SP)
. . 466ef5: MOVQ $0x0, 0x60(SP)
. . 466efe: MOVQ $0x0, 0x68(SP)
. . 466f07: LEAQ 0x70d92(IP), AX
. . 466f0e: MOVQ AX, 0(SP)
. . 466f12: LEAQ 0x70(SP), AX
. . 466f17: MOVQ AX, 0x8(SP)
. . 466f1c: MOVQ $0x0, 0x10(SP)
15.41 MB 15.41 MB 466f25: CALL runtime.convT2E(SB)
. . 466f2a: MOVQ 0x18(SP), AX
. . 466f2f: MOVQ 0x20(SP), CX
. . 466f34: MOVQ AX, 0x60(SP)
. . 466f39: MOVQ CX, 0x68(SP)
. . 466f3e: LEAQ 0x10b35b(IP), AX
. . 466f45: MOVQ AX, 0(SP)
. . 466f49: MOVQ 0x58(SP), AX
. . 466f4e: MOVQ AX, 0x8(SP)
. . 466f53: LEAQ 0x99046(IP), CX
. . 466f5a: MOVQ CX, 0x10(SP)
. . 466f5f: MOVQ $0xd, 0x18(SP)
. . 466f68: LEAQ 0x60(SP), CX
. . 466f6d: MOVQ CX, 0x20(SP)
. . 466f72: MOVQ $0x1, 0x28(SP)
. . 466f7b: MOVQ $0x1, 0x30(SP)
. 12.02 kB 466f84: CALL fmt.Fprintf(SB)

Якась функція runtime.convT2E виділила всю цю пам'ять. Що це?

Давайте подивимося на те, як визначена функція fmt.Fprintf():

func Fprintf(w io.Writer, format string, a ...interface{}) (int n, err error)

Оскільки функція повинна приймати будь-який тип, її аргументи визначені як порожній інтерфейс. Порожній інтерфейс, по суті, це аналог void* в С.

Але ми не можемо просто «скастовать» все що завгодно інтерфейс, т. до. ми втратимо інформацію про тип. Все що завгодно інтерфейс треба перетворити, і це перетворення іноді вимагає додаткової пам'яті? Чому? Давайте зануримося трохи глибше типи мови Go.

В Go існують вбудовані типи, такі як string, chan, func, slice, interface і т. д. Кожен з них має в пам'яті певну структуру.

Давайте подивимося, що представляє із себе string, оскільки саме цей випадок ми розглядаємо:



Рядок — це 16 байт. Перші 8 байт — вказівник на иммутабельный масив, в якому, власне, лежить рядок, а другі 8 байт — довжина рядка.

А тепер подивимося на interface. Interface в пам'яті теж являє собою два 8-байтних шматка.



Перші 8 байт — вказівник на внутрішню структуру, що містить інформацію про тип, а другі 8 байт — власне вказівник на об'єкт.

Якщо б ми зробили

var s string = "marko"
var a interface{} = &s

то ніякої додаткової пам'яті нам не потрібно, адже ми можемо відразу в другі 8 байт інтерфейсу покласти покажчик на рядок.

Але це не наш випадок. Ми прирівнюємо до інтерфейсу не дороговказ, а значення:

var s string = "marko"
var a interface{} = s

У такому разі Go доводиться виділити додаткову проміжну структуру за допомогою функції runtime.convT2E.

Результат виглядає наступним чином:



Саме ці 16 байт ми бачили у виведенні go test.

Давайте тепер спробуємо позбутися від цього «зайвого» виділення пам'яті.
Ми замінюємо fmt.Fprintf на послідовну запис в буфер конкретно рядків:

package main

import (
"bytes"
"testing"
)

func BenchmarkPrint(b *testing.B) {
var buf bytes.Buffer
var s string = "test string"
for i := 0; i < b.N; i++ {
buf.Reset()
buf.WriteString("string is: ")
buf.WriteString(s)
}
}

І очікувано отримаємо 0 виділень:

$ go test bench=BenchmarkPrint -benchmem
testing: warning: no to run tests
BenchmarkPrint-8 50000000 27.5 ns/op 0 B/op 0 allocs/op
PASS
ok github.com/mkevac/converttest01 1.413 s

Заодно код прискорився в 4 рази.

Неявне виділення (2)
Другий приклад повинен бути близький «сишникам» і тим, хто використовує cgo. Адже З рядок (char *) і масив байт — це, по суті, одне і те ж. Можна конвертувати одне в інше, хіба що про нульовий байт в кінці подбати.

В Go, як ми вже бачили, це не так. Рядок — це не просто вказівник на масив, це також і довжина.

Тому простенька програма типу

package main

import (
"fmt"
)

func main() {
var array = []byte{'m', 'a', 'r', 'k', 'o'}
if string(array) == "marko" {
fmt.Println("equal")
}
}

приводила до виділення пам'яті, щоб перетворити масив в рядок. Насправді це так і було до недавнього часу. git-blame каже, що Дмитро Вьюков полагодив цей кейс. А точніше, зробив так, що якщо наша змінна не використовується за межами функції (do not escapes to heap), то можна виділити пам'ять для неї на стеку, а не в купі.

Цей кейс дуже добре підводить нас до важливої думки. Будь-які оптимізації, які ми робимо, будь-які нюанси, про які ми знаємо, найближчим часом можуть застаріти. Розробники мови щодня покращують компілятор і runtime. Я сподіваюся, що моя стаття дасть вам достатньо інструментів, щоб ви могли перевіряти свої гіпотези, добиратися до суті, а не бездумно слідувати радам з інтернету 2010 року, які можуть бути не тільки марні, але й шкідливі в поточний момент.

Але повернемося до нашого прикладу.

Щоб все-таки навести приклад, мені довелося трохи обдурити Go-компілятор і переконати його, що рядок escapes to heap.

Давайте подивимося на нього:

package main

import (
"bytes"
"testing"
"unsafe"
)

var s string

func BenchmarkConvert(b *testing.B) {
var buf bytes.Buffer
var array = []byte{'m', 'a', 'r', 'k', 'o', 0}
for i := 0; i < b.N; i++ {
buf.Reset()
s = string(array)
buf.WriteString(s)
}
}

$ go test bench=. -benchmem
testing: warning: no to run tests
BenchmarkConvert-8 30000000 42.1 ns/op 8 B/op 1 allocs/op

Такий кейс найчастіше виправляється ручним створенням структури рядка з використанням пакетів reflect і unsafe.

func BytesToString(b []byte) string {
bh := (*reflect.SliceHeader)(unsafe.Pointer(&b))
sh := reflect.StringHeader{bh.Data, bh.Len}
return *(*string)(unsafe.Pointer(&sh))
}

func BenchmarkNoConvert(b *testing.B) {
var buf bytes.Buffer
var array = []byte{'m', 'a', 'r', 'k', 'o', 0}
for i := 0; i < b.N; i++ {
buf.Reset()
s = BytesToString(array)
buf.WriteString(s)
}
}

Аллокаций в цьому випадку більше немає.

$ go test bench=. -benchmem
testing: warning: no to run tests
BenchmarkConvert-8 30000000 44.5 ns/op 8 B/op 1 allocs/op
BenchmarkNoConvert-8 100000000 19.2 ns/op 0 B/op 0 allocs/op
PASS
ok github.com/mkevac/bytetostring 3.332 s

Трейсінг
Ще одна чудова можливість, яку надає Go — трейсінг. Коли ви включаєте трейсінг, Go runtime записує у файл в дуже компактному вигляді майже все, що робить, і те, що відбувається з горутинами і тредами: очікування на каналі, старт після очікування на каналі, локі, системні виклики і т. д. Повний список з коментарями можна подивитися в исходниках Go на початку файлу runtime/trace.go.

Друга частина трейсинга — візуалізація в браузері. Для цього використовується той же самий пакет, що і в Chrome для візуалізації завантаження веб-сторінки.

Ну що ж, давайте спробуємо і подивимося, як виглядає трейсінг.

Приклад
Якийсь час тому я написав пакет для візуалізації споживання пам'яті і GC-пауз під назвою debugcharts.



Пакет разів в секунду отримує дані про споживання пам'яті командою runtime.ReadMemStats(), про завантаження процесора і GC-паузах і малює ці дані у вигляді інтерактивного графіка в браузері.

Давайте зробимо маленьку програму, яка буде в двох потоках просто «палити процесор», і скористаємося моїм пакетом debugcharts.

package main

import (
"net/http"
_ "net/http/pprof"
"time"

_ "github.com/mkevac/debugcharts"
)

func CPUHogger() {
var acc uint64
t := time.Tick(2 * time.Second)
for {
select {
case <-t:
time.Sleep(50 * time.Millisecond)
default:
acc++
}
}
}

func main() {
go CPUHogger()
go CPUHogger()
http.ListenAndServe("0.0.0.0:8181", nil)
}

Запустимо програму і скористаємося утилітою trace, щоб побачити, як ця програма працює.

Для початку візьмемо трейс за 10 секунд. Будьте уважні: якщо ваша програма дуже сильно навантажена і runtime постійно щось робить, то ви зможете зібрати дані за 1-3 секунди максимум. На жаль, візуалізатор Chrome і JavaScript більше даних просто не потягнуть.

curl http://localhost:8181/debug/pprof/trace?seconds=10 -o trace.out

А потім запустимо утиліту go tool trace, щоб візуалізувати цей трейс:

go tool trace -http "0.0.0.0:8080" ./tracetest trace.out

Відкриється браузер, і ми побачимо приблизно наступну картину:



У нас тут є можливість подивитися на працюючі горутины:



Видно, що горутин, активно споживають процесор, дві. Якщо ми натиснемо на посилання, ми отримаємо трохи більш докладні дані про те, на що витрачала час ця горутина.



Як бачите, даних просто море, але якщо ми натиснемо на саму першу посилання, то отримаємо основну візуалізацію, яка виглядає наступним чином:



Ми бачимо, що в основному працюють 4 процесора, і що горутины іноді перестрибують з процесора на процесор, і що раз в 2 секунди процес спить 50 мілісекунд, як і написано в коді. Бачимо, що раз в секунду щось відбувається, і це, напевно, якраз збір даних для debugcharts. Начебто все виглядає так, як повинно.

Але давайте спробуємо збільшити те місце, де раз у секунду збираються дані для debugcharts:



Ми можемо помітити що-то дивне. Debugcharts працює, а дві інші горутины, які повинні навантажувати процесор, не працюють. І така картина повторюється кожну секунду.

Якщо ми виділимо маленькі лінії після зелених і синіх прямокутників і ті, що до зелених і синіх прямокутників, то побачимо, що це події proc stop і proc start відповідно.

Я відтворив для вас саме ту ситуацію, з якою зіткнувся, коли спробував запустити debugcharts в продакшені. Раз в секунду latency сервісу значно підвищувалася.

Швидко заглянувши в исходники runtime.ReadMemStats(), я побачив проблему.

180 // ReadMemStats populates m with memory allocator statistics.
181 func ReadMemStats(m *MemStats) {
182 stopTheWorld("read mem stats")
183
184 systemstack(func() {
185 readmemstats_m(m)
186 })
187
188 startTheWorld()
189 }

Ця функція зупиняє світ на час своєї роботи. І саме це ми бачимо у браузері.

Як ви розумієте, debugcharts в продакшен не пішов і залишився утилітою для розробки.

Висновок
Стаття вже вийшла досить об'ємною навіть незважаючи на те, що я встиг розглянути тільки малу частину з того, про що хотів розповісти.



Ще раз перерахуємо ті засоби, що доступні в Go:

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


Як ви бачите, мова Go володіє чудовим інструментарієм для оптимізації, дебагинга і взагалі для того, щоб бачити, що відбувається в програмі.

На додаток до інструментів Go, ви можете скористатися тими засобами, які є в ОС. Сьогодні ми розглянули лише деякі приклади застосування perf і SystemTap. Таких утиліт набагато більше.

Незважаючи на наявність великої кількості потужних і зручних інструментів, розуміння того, що відбувається у вашій програмі на всіх рівнях — від заліза, ядра ОС і до функцій, які ви написали, — є основоположним при профілюванні та оптимізації.

Я сподіваюся, що ця стаття виявиться корисною для вас. Stay curious!

Марко Кевац, програміст у відділі C/C++ розробки
Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.