Go: контексти з таймаутом та підводні камені
Привіт, мене звати Макс Багінський, я Head of Engineering у Solidgate — українській продуктовій фінтех-компанії, що працює в ніші пейментів і допомагає розбудовувати платіжну інфраструктуру для інтернет-бізнесів у всьому світі.
Наша інженерна команда працює з відносно великим навантаженням — у нас близько
Основний стек, на якому працює наша команда, — Go. Високе навантаження, розвинена інфраструктура продукту та суворі очікування фінтех-ринку вимагають постійної роботи нашої інженерної команди на покращення коду. У цьому матеріалі хочу розглянути один із наших кейсів і зануритися під капот Go. Сподіваюсь переконати вас, що експертизу треба та можна поглиблювати завжди, а також поділюсь матеріалами про те, як дебажити складні проблеми в Go-коді.
У роботі ми активно використовуємо пакет context у Go. Він корисний під час взаємодії з АРІ та повільними процесами, особливо у production-grade-системах, що займаються вебзапитами. З його допомогою можна повідомити горутини про необхідність завершити свою роботу.
Зануримось трошки в горутини. В офіційній документації горутина — це функція, що виконується конкурентно з іншими горутинами на одному треді. Для комунікації між собою горутини можуть використовувати канали для передачі результатів, помилок або іншої інформації з однієї горутини до іншої. Наприклад, канал типу int отримує цілі числа, error — помилки тощо.
До суті
У роботі ми часто використовуємо контекст із таймаутом. Він працює в структурі механізму батчінгу мерчантських логів. Мерчантські логи — це інформація про запити по платіжним транзакціям. Вони дозволяють мерчантам (клієнтам) відстежувати статуси платежів протягом усього циклу платежу.
Фактично, вся взаємодія з нашим АРІ логується як зі сторони прямого доступу до АРІ, так і зі сторони відправки вебхуків (асинхронних апдейтів з платежів). Для чого? Щоб зібрати повний «трейс» взаємодії з нашим АРІ та допомогти вирішити будь-яку проблему по запиту клієнту — наприклад, про статуси платежів на будь-якому етапі оплати.
Приклад платежу в адмінці для мерчантів
Вимоги до імплементації батчінгу логів доволі прості: збір усіх логів, запис їх у базу з мінімальною затримкою (тобто батчер не має накладати додаткових витрат з часу). Рішення має працювати за будь-якого навантаження. Нам також потрібно уникати складних логік з worker pools, щоб не переускладнювати сам код.
Імплементація батчеру та проблема
Ось так виглядає асинхронний батчер:
У батчері є слайс, розмірність якого задається на етапі ініціалізації. Кожен елемент слайсу — окремий бакет елементів зі своїм воркером, який по таймеру зберігає дані в бакеті та очищає його. Фактично, будь-який паралелізм буде безпечним, якщо працювати з окремими бакетами. Під час використання батчеру ми задавали доволі короткий проміжок часу, щоб він не впливав на виконання запиту мерчанта. Для цього створювали контекст з 5 мс таймаутом.
Основна частинка коду з якою будемо працювати:
func (b *AsyncBatcher[Item]) Batch(ctx context.Context, item Item) error {
idx := atomic.AddInt64(&b.count, 1) // інкрементуємо каунтер кількості елементів
batchIdx := (idx / b.size) % 100
select {
case b.batches[batchIdx] <- item: // вставляємо елемент
return nil // вставка пройшла успішно
case <-ctx.Done(): // чи закінчився контекст
return ctx.Err() // повертаємо помилку
}
}
Тут можна ознайомитись з усім кодом, про який йдеться в статті
Інкрементуємо каунтер кількості елементів, визначаємо бакет, у який покласти елемент звичайним залишком від ділення, та пробуємо покласти в бакет. Додатково перевіряємо, що контекст все ще «живий». Бакети призначені для накопичення батчів та їхньої паралельної обробки. Кожен бакет має свій воркер, який періодично «флашить» елементи далі. Так ми можемо накопичувати дані в батчі й обробляти їх з мінімальними блокуваннями.
Дебаг
Приблизно раз у декілька днів помилка Context Canceled «стріляла нам у ногу» разом з алертом в командний чат. Команда platform швидко реагувала на нього, аналізувала логи, встановлювала проблемне місце та, на жаль, нічого зробити не могла. Хоч код під час використання контексту був на кшталт двох простих математичних операцій на ділення та запис, контекст скасовувався з незрозумілих причин.
Витративши якусь частину часу було ухвалене рішення збільшити таймаут контексту до 100 мс. Але було зрозуміло — це лише тимчасове рішення до моменту встановлення реальної причини скасування контексту. Дозволити собі ввімкнути трейсинг Go runtime на Production ми не могли, а отримати результат без трафіку на Stage неможливо.
Банальна рекомендація «напишіть бенчмарк і протестуйте його» спрацювала б у більшості випадків, але бенчмарки вже були.
Як виглядав звичайний бенчмарк батчера?
func BenchmarkAsyncBatcher_BatchSizeThirty(b *testing.B) {
bb := batcher.NewAsync[int](30, time.Millisecond*100, func(items []int) {
}) // метод запису елементів в сховище
b.SetParallelism(10) // виставляємо кількість паралельних горутин
b.ReportAllocs() // вмикаємо репорт по аллокаціям
b.RunParallel(func(pb *testing.PB) { // запускаємо бенчмарк
for pb.Next() {
if err := bb.Batch(context.Background(), 1); err != nil { // виклик батчеру
panic(err)
}
}
})
}
Виставляємо кількість так, щоб навантажити батчер в 10 горутин. Розмір батчера — 30 елементів в 100 бакетах (це дефолтне налаштування батчера), флаш-бакету раз на 100 мс. Бенчмарк, на жаль, не ловив проблему, а лише допомагав оцінити ефективність рішення.
Проблема продовжувала виникати за магічних для нас обставинах — ми не розуміли, як її повторити, щоб відстежити результат. Ми писали бенчмарки з різними таймаутами та кількістю ядер, щоб добитися скасування контексту. Витративши понад шість годин, нам вдалося повторити ситуацію скасування за контексту в 5 мс, а бенчмарк падав приблизно раз в 10 хвилин.
Ось як виглядав фінальний бенчмарк. Для більшого контролю ми перевели його в тест (testing.B → testing.T):
func TestAsync_Batch(t *testing.T) {
bb := batcher.NewAsync[int64](5, time.Millisecond*100, func(items []int64) {}) // створюємо батчер
var n int64
for {
ctx, _ := context.WithTimeout (context.Background(), time.Millisecond*5) // cтворюємо контекст
n1 := atomic.AddInt64(&л, 1) // робимо каунтер елементів і використовуємо як значення
if err:= bb.Batch(ctx, n1); err != nil { // викликаємо батчер
panic(err)
}
time.Sleep (time.Millisecond * 300) // симулюємо 3 rps але послідовних
}
}
Після повторення чогось схожого на production-код ми вирішили додати також і рантайм трейсинг в бенчмарк.
func TestAsync_Batch(b *testing.T) {
bb := batcher.NewAsync[int64](5, time.Millisecond*100, func(items []int64) {})
ftrace, err := os.Create("trace.out")
if err != nil {
panic(err)
}
defer ftrace. Close()
if err := trace.Start(ftrace); err != nil {
panic (err)
}
defer trace. Stop ()
var n int64
for {
ctx, _ := context .WithTimeout (context.Background(), time.Millisecond*5)
n1 := atomic.AddInt64 (&n, 1)
if err := bb.Batch(ctx, n1); err != nil {
panic(err)
}
time.Sleep(time.Millisecond * 300)
}
}
Одне з зауважень — важливо було запускати тест з обмеженням кількості потоків!
Приклад запуску:
GOMAXPROCS=1 GODEBUG=gctrace=1, schedtrace=500, scheddetail=1 go test -run TestAsync_Batch
GODEBUG трішки допоможе нам в розумінні того, що ми робимо і чи робимо ми це правильно. А ще й виведе статус по кожній з горутин, покаже деталі по переключенню та виклики garbage collector.
shedtrace=500 — параметр як часто виводити інформацію по дебагу в логи, тобто раз в 500 мс.
SCHED Oms: gomaxprocs=1 idleprocs=0 threads=3 spinningthreads=0 needspinning=1 idlethreads=0 runqueue=0 gcwaiting=false nmidlelocked=0 stopwait=0 sysmonwait=false PO: status=1 schedtick=0 syscalltick=0 m=2 runqsize=2 gfreecnt=0 timerslen=0 M2: p=0 curg=4 mallocing=0 throwing=0 preemptoff= locks=3 dying=0 spinning=false blocked=false lockedg=nil M1: p=nil curg=nil mallocing=0 throwing=0 preemptoff= locks=2 dying=0 spinning=false blocked=false lockedg=nil MO: p=nil curg=nil mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=1 G1: status=1(chan receive) m=nil lockedm=0 G2: status=1() m=nil lockedm=nil G3: status=1() m=nil lockedm=nil G4: status=2() m=2 lockedm=nil
Але повернемось до дебагу. За допомогою такого бенчмарку та окремо збору трейсу вдалось виявити проблему:
SCHED 405538ms: gomaxprocs=1 idleprocs=0 threads=4 spinningthreads=0 needspinning=1 idlethreads=2 runqueue=0 gcwaiting=false nmidlelocked=0 stopwait=0 sysmonwai†=false
PO: status=1 schedtick=176632 syscalltick=307 m=0 runqsize=3 gfreecnt=4 timerslen=2
M3: p=nil curg=nil mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=nil
M2: p=nil curg=nil mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=nil
M1: p=nil curg=nil mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=nil
MO: p=0 curg=6 mallocing=1 throwing=0 preemptoff= locks=2 dying=1 spinning=false blocked=false lockedg=nil
G1: status=4(chan receive) m=nil lockedm=nil
G2: status=4(force gc (idle)) m=nil lockedm=nil
G3: status=4(GC sweep wait) m=nil lockedm=nil
G4: status=4(GC scavenge wait) m=nil lockedm=nil
G5: status=4(finalizer wait) m=nil lockedm=nil
G6: status=2 (semacquire) m=0 lockedm=nil
G7: status=4(select) m=nil lockedm=nil
G8: status=4(select) m=nil lockedm=nil
G9: status=4(select) m=nil lockedm=nil
G10: status=4(select) m=nil lockedm=nil
...
G107: status=6() m=nil lockedm=nil
G371122: status=1() m=nil lockedm=nil
G371124: status=6() m=nil lockedm=nil
G371121: status=1() m=nil lockedm=nil
G5662: status=4(GC worker (idle)) m=nil lockedm=nil
G371120: status=6() m=nil lockedm=nil
G371123: status=1() m=nil lockedm=nil
G368518: status=6() m=nil lockedm=nil
panic: start time: 342169000, contextCreated: 354665000, end time: 354670000, isCanceled: true, deadline: 347170000
goroutine 6 [running]:
testing. tRunner. func1.2({0x100dbcb40, 0x140000d4f50})
/usr/local/go/src/testing/testing.go:1526 +0x1c8
testing. tRunner. func1()
/usr/local/go/src/testing/testing.go:1529 +0x364
panic({0x100dbcb40, 0x140000d4f50})
/usr/local/go/src/runtime/panic.go:884 +0x1f4
github.com/makasim/batcher. (*AsyncBatcher[...]) .Batch(0x1400001a0a8, {0x100df4348?, 0x140000db260}, 0x5a94b)
/Users/maximbaginskiy/work/batcher/async.go:57 +0x1d4
github.com/makasim/batcher_test.TestAsyncBatcher_Batch2 (0x0?)
/Users/maximbaginskiy/work/batcher/async_benchmark_test.go:208 +0x164
testing. tRunner (0x14000005d40, 0x100dflec8)
/usr/local/go/src/testing/testing.go:1576 +0x104
created by testing. (*T).Run
/usr/local/go/src/testing/testing.go:1629 +0x370
exit status 2
FAIL github.com/makasim/batcher 405.9635
Що ми бачимо з цього результату?
За час роботи програми було створено сотні тисяч окремих горутин, хоча в самому коді напряму ми їх не створювали. З дебагу видно, що остання горутина, що працює, до падіння тесту має індекс на десятки тисяч нижчий за інші горутини — G371120 та G368518. Це значить, що шедулер повернувся до цієї горутини сильно пізніше і встиг настворювати й обробити багато інших горутин. Віддавши перевагу новим горутинам і створив ситуацію, де деякі старі горутини не були навіть запущені.
G371120: status=6() m=nil lockedm=nil G371123: status=1() m=nil lockedm=nil G368518: status=6() m=nil lockedm=nil
Це також було підтверджено трейсом, який ми завчасно додали до тесту:
~ go tool trace trace.out
У колонці Scheduler wait видно, що шедулер може очікувати / блокувати горутини на доволі тривалий час
Додавши трішки врапінгу помилок та контексту, знайшли ще одну проблему — одразу ж після створення контексту з Deadline він створився закінченим.
...
defer f.Close()
if err := pprof.Lookup("block") .WriteTo(f, 0); err != nil {
panic(err)
}
var n int64
for {
startTime := time.Now()-Nanosecond() // беремо поточний час
ctx, _ := context.WithTimeout (context.Background(), time.Millisecond*5) // створюємо короткий таймаут
contextCreated := time.Now().Nanosecond() // беремо час після створення контексту
deadline, isClosed := ctx.Deadline() // перевіряємо чи робочий ще контекс
n1 := atomic.AddInt64 (&n, 1)
if err:= bb.BatchExtended(ctx, n1, startTime, contextCreated, deadline.Nanosecond(), isClosed); err != nil {
panic(err)
}
time.Sleep(time.Millisecond * 1)
}
panic: start time: 342169000, contextCreated: 354665000, end time: 354670000, isCanceled: true, deadline: 347170000
Чому так може виникати
Створення контексту з таймаутом або дедлайном викликає лок м‘ютекса в контексті. Через це шедулер може передати виконання наступній у черзі горутині. Ось для прикладу код зі стандартної бібліотеки на створення контексту з коментарем, на який варто звернути увагу:
func WithDeadlineCause(parent Context, d time.Time, cause error) (Context, CancelFunc) {
if parent == nil {
panic("cannot create context from nil parent")
}
if cur, ok := parent.Deadline(); ok && cur.Before(d) {
// The current deadline is already sooner than the new one.
return WithCancel(parent)
}
c := &timerCtx{
deadline: d,
}
c.cancelCtx.propagateCancel(parent, c)
dur := time.Until(d)
if dur <= 0 {
c.cancel(true, DeadlineExceeded, cause) // deadline has already passed
return c, func() { c.cancel(false, Canceled, nil) }
}
c.mu.Lock()
defer c.mu.Unlock()
if c.err == nil {
c.timer = time.AfterFunc(dur, func() {
c.cancel(true, DeadlineExceeded, cause)
})
}
return c, func() { c.cancel(true, Canceled, nil) }
}
Фактично, ми спавнили десятки тисяч горутин і забивали шедулер, що блокувало його менш ніж на секунду (наприклад network call на сервіс). Цього вистачало, щоб під час спроби записати дані в бакет ми отримували проекспайрений контекст (або ж він закінчувався на момент повернення рантайму до місця запису). Говорячи про реальний сервіс, Go http-сервер також створює додаткові горутини і додає їх в чергу на обробку. Це все призводить до того, що таймери експайряться ще до фактичного їхнього використання. Це навіть трішки нагадує роботу JavaScript (повна «асинхронщина»).
Що сталось
Хоч робота з контекстами здавалась зовсім не складною, бувають ситуації, де поведінка програми не зрозуміла. На такому етапі потрібно вчитися розбиратися з проблемою.
Маючи велику кількість CPU bound операцій в коді або сервісі та недостатню кількість ресурсів, може траплятися ситуація, коли контексти створюються вже скасованими. Найчастіше вона виникає, коли мікросервісам доступно від 0.5 CPU до 1 CPU і навіть за невеликого навантаження. Але як це можливо?
Контексти часто використовуються для передачі різних типів сигналів. Одне з місць, де вони створюються автоматично, це стандартний http-сервер. Під час опрацювання будь-якого запиту контексти дозволяють переривати повільні запити до бази даних, довгі операції або виклики зовнішніх сервісів. Також контексти можна використовувати в Graceful shutdown-механізмі. У більшості ситуацій контексти використовуються для контролю за часом та скоупом виконання будь-якої операції, або ж навіть за контролем рантайму.
Шедулінг у Go
Уже доволі давно Вільям Кенеді у своєму мікроциклі статей про шедулінг розповів основну теорію роботи шедулера як зі сторони операційної системи, так і зі сторони Go Runtime.
Go Scheduler працює в рантаймі та перебуває фактично зверху шедулера операційної системи, прив‘язується до потоків, які створюються під час старту апплікейшену. Кожен потік має свою чергу горутин, з якою працює, а перемикання відбувається за наступних умов: створення горутини (використання ключового слова go), системні виклики, синхронізація по типу mutex або select.
Операції поділяються в основному на два типи:
- CPU Bound — операції, які працюють майже без перемикання контексту і в основному обмежуються швидкістю роботи центрального процесору. Для прикладу — шифрування, робота з даними в оперативній пам‘яті.
- IO Bound операції — операції, які працюють з частим перемиканням контексту й обмежуються лише кількістю перемикань і швидкістю читання / запису із зовнішніх ресурсів. Наприклад, мережевий запит, запис на диск.
За наявності великої кількості CPU Bound операцій та невеликої кількості доступних ядер процесора розбиття операцій горутинами не матиме особливого сенсу. У більшості кейсів ми використовуємо Go як мову для бекенду, де IO-операції превалюють над кількістю CPU-операцій.
Ще одним з важелів впливу на роботу шедулера являється Garbage Collector (GC), який може блокувати програму на деякий час, щоб вивільнити частину пам‘яті за досягнення критичних показників. Доволі детально про те, як GC може впливати на процес виконання програми, описано в блозі.
Якщо вам цікаво більше дізнатись про роботу шедулера — переходьте сюди.
Висновки та результати
Занурившись у теорію та стикнувшись з челенджами з контекстами, тепер ми знаємо, що:
- Використовувати контексти для батчінгу не потрібно. Ми будемо пропускати івент у випадку, якщо бакет заповнений, — хоч ця ситуація і може виникнути лише під час екстремальних навантаженнях у десятки або сотні тисяч rps за правильного налаштування батчеру.
- Краще не використовувати короткі таймери на операціях, якщо у вас обмежені ресурси. Контексти з дедлайном або таймаутом створюють нові горутини та додають зайвої роботи шедулеру.
- Якщо кількість CPU-bound-операцій велика — таймери можуть закінчуватись не тоді, коли потрібно або не тоді, коли очікується. Варто правильно обробляти кейси з протермінованими таймерами.
- Велика кількість контекстів з таймером або дедлайном може проекспайритись ще до використання.
- Створення великої кількості таймерів або тікерів може призвести до Time warp (лінк). Потрібно оптимізувати роботу з ними, наприклад, через timer pool.
- Іноді time.Sleep буде кращим рішенням за будь-який таймер чи тікер. Він не створює додаткове навантаження на шедулер у вигляді нової горутини. У деяких випадках краще зовсім відмовитись від використання контексту та таймерів.
Сподобалась стаття? Підписуйтесь на автора, щоб отримувати сповіщення про нові публікації на пошту.
Vitaliy Fedoriv
Dmytro Vynokurov
юнит тест
Igor Prots
anonymous
schwarzlichtbezirk
schwarzlichtbezirk
anonymous
Roman Kosyi
юнит тест
Petro Kvartsianyi
21 коментар
Додати коментар Підписатись на коментаріВідписатись від коментарів