Блог

Предыстория

Когда я запускаю нагрузочный тест в приложении, которое я создаю, все работает гладко, пока на компьютере почти не закончится память, и приложение не столкнется с проблемами. Внезапно все контексты отменяются (скорее всего, библиотекой hystrix), потому что обработка запросов занимает слишком много времени. Пока ничего удивительного.

Проблема

Что я нахожу странным, так это то, что, похоже, начинается утечка подпрограмм go при отмене контекстов.

В нормальных условиях постоянно работает около 20 подпрограмм. Но после того, как эта ситуация произойдет, в ней останется более 20 подпрограмм: 98, если быть точным. Это число не уменьшается со временем. Я использую http.Сервер с тайм-аутами чтения / записи, go-sql-driver / mysql и hystrix с контекстом. Ниже приведен дамп подпрограмм, которые выполняются намного дольше, чем все тайм-ауты. Почти все они исходят из go-sql-driver или вызываются им. В списке процессов MySQL не осталось запросов. Любопытно, испытал ли это кто-то еще и знает, как это решить.

После этого приложение по-прежнему работает бесперебойно и может обрабатывать более 2000 об / с со 100% вероятностью успеха, но после завершения теста предыдущие зависшие подпрограммы все еще существуют.

Вот дамп подпрограмм (не все, но это больше похоже). runtime_pollWait из go-mysql-driver:

 goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x7fd0fbc007b8, 0x72, 0x0)

goroutine 18 [sleep, 43 minutes]:
runtime.goparkunlock(...)

goroutine 19 [select, 2 minutes]:
database/sql.(*DB).connectionOpener(0xc000188240, 0xb835a0, 0xc00017b2c0)

goroutine 20 [select]:
database/sql.(*DB).connectionResetter(0xc000188240, 0xb835a0, 0xc00017b2c0)

goroutine 34 [select, 2 minutes]:
database/sql.(*DB).connectionOpener(0xc0001883c0, 0xb835a0, 0xc00016a140)

goroutine 35 [select]:
database/sql.(*DB).connectionResetter(0xc0001883c0, 0xb835a0, 0xc00016a140)

goroutine 8 [chan receive]:
github.com/go-redis/redis/internal/pool.(*ConnPool).reaper(0xc0000ba370, 0xdf8475800)

goroutine 11 [chan receive]:
github.com/go-redis/redis/internal/pool.(*ConnPool).reaper(0xc0000ba420, 0xdf8475800)

goroutine 14 [chan receive]:
github.com/go-redis/redis/internal/pool.(*ConnPool).reaper(0xc0000ba4d0, 0xdf8475800)

goroutine 98 [sleep, 43 minutes]:
runtime.goparkunlock(...)

goroutine 87 [chan receive]:
github.com/afex/hystrix-go/hystrix.(*metricExchange).Monitor(0xc002a1b5c0)

goroutine 99 [syscall]:
syscall.Syscall6(0xe8, 0xd, 0xc0002b9a58, 0x64, 0x64, 0x0, 0x0, 0x42bfcf, 0x8, 0xacdd80)

goroutine 100 [sleep]:
runtime.goparkunlock(...)

goroutine 88 [chan receive]:
github.com/afex/hystrix-go/hystrix.(*poolMetrics).Monitor(0xc003ac08a0)

goroutine 91 [chan receive]:
github.com/afex/hystrix-go/hystrix.(*metricExchange).Monitor(0xc002a1b680)

goroutine 92 [chan receive]:
github.com/afex/hystrix-go/hystrix.(*poolMetrics).Monitor(0xc003ac0f00)

goroutine 25921733 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06f298, 0x72, 0xffffffffffffffff)

goroutine 25921439 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0f983fe18, 0x72, 0xffffffffffffffff)

goroutine 25927120 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc003aa7620, 0xc01c2ef980, 0xc01a841bc0)

goroutine 25928175 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc012abbf80, 0xc01c2ee600, 0xc01144f8c0)

goroutine 25927727 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc014ae4300, 0xc0166a3c80, 0xc0030e8a80)

goroutine 24567262 [select]:
database/sql.(*DB).connectionCleaner(0xc000188240, 0x2540be400)

goroutine 25927990 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc012ababa0, 0xc0166a3ec0, 0xc01144f380)

goroutine 25921926 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa0702d8, 0x72, 0xffffffffffffffff)

goroutine 25921958 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06eb48, 0x72, 0xffffffffffffffff)

goroutine 24567381 [select]:
database/sql.(*DB).connectionCleaner(0xc0001883c0, 0x2540be400)

goroutine 25921798 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0f9882038, 0x72, 0xffffffffffffffff)

goroutine 25921751 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa6b6820, 0x72, 0xffffffffffffffff)

goroutine 25921757 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa6b6410, 0x72, 0xffffffffffffffff)

goroutine 25927113 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc003aa7320, 0xc01c2efbc0, 0xc01a8419e0)

goroutine 25921966 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06e8d8, 0x72, 0xffffffffffffffff)

goroutine 25921964 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06e9a8, 0x72, 0xffffffffffffffff)

goroutine 25921323 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06f0f8, 0x72, 0xffffffffffffffff)

goroutine 25928466 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e552240, 0xc01c2ef740, 0xc01144f920)

goroutine 25928011 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc0156599e0, 0xc01c2ee3c0, 0xc01baa8fc0)

goroutine 25919812 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06ea78, 0x72, 0xffffffffffffffff)

goroutine 25928014 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc015659b00, 0xc01177e900, 0xc01baa90e0)

goroutine 25922001 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa070548, 0x72, 0xffffffffffffffff)

goroutine 25925675 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa6b8150, 0x72, 0xffffffffffffffff)

goroutine 25928529 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc003aa7680, 0xc01c2ef8c0, 0xc01a841c20)

goroutine 25928467 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e552360, 0xc01c2ef680, 0xc01144f980)

goroutine 25928468 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e552480, 0xc01c2ef5c0, 0xc01144f9e0)

goroutine 25919817 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06e808, 0x72, 0xffffffffffffffff)

goroutine 25925511 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0f983e4e8, 0x72, 0xffffffffffffffff)

goroutine 25920658 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa070208, 0x72, 0xffffffffffffffff)

goroutine 25920661 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa070138, 0x72, 0xffffffffffffffff)

goroutine 25920667 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06e738, 0x72, 0xffffffffffffffff)

goroutine 25920860 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06f368, 0x72, 0xffffffffffffffff)

goroutine 25920790 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa070478, 0x72, 0xffffffffffffffff)

goroutine 25920793 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa06fec8, 0x72, 0xffffffffffffffff)

goroutine 25928006 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc015659800, 0xc01c1603c0, 0xc01baa8de0)

goroutine 25921085 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa6b7fb0, 0x72, 0xffffffffffffffff)

.....

goroutine 25925779 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa6b7ba0, 0x72, 0xffffffffffffffff)

goroutine 25926131 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7fd0fa6b69c0, 0x72, 0xffffffffffffffff)

goroutine 25927988 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc012abaae0, 0xc01c2ee000, 0xc01144f2c0)

goroutine 25928470 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e5526c0, 0xc01c2ef440, 0xc01144faa0)

goroutine 25928471 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e5527e0, 0xc01c2ef380, 0xc01144fb00)

goroutine 25928472 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e552900, 0xc01c2ef2c0, 0xc01144fb60)

goroutine 25928473 [select, 3 minutes]:
github.com/go-sql-driver/mysql.(*mysqlConn).startWatcher.func1(0xc00e552a20, 0xc01c2ef200, 0xc01144fbc0)

goroutine 26252345 [IO wait]:
internal/poll.runtime_pollWait(0x7fd0e7054fe8, 0x72, 0xffffffffffffffff)
  

Чтобы ответить на мой собственный вопрос; проблема, скорее всего, в перегрузке системы. Я оцениваю ограниченное количество одновременных подключений и использую намного меньше подключений к MySQL на 25%. Похоже, это решает проблему. Теперь у меня меньшая пропускная способность, но более стабильная система.

Он по-прежнему не отвечает, почему netpoller продолжает блокировать, даже когда система снова успокоилась. Они просто никогда не восстанавливаются, что, я думаю, нехорошо. Но, вероятно, для этого есть веская причина. Я несколько раз видел эти симптомы в Stackoverflow с сетевыми подключениями, такими как, например, http.Клиент.