dasha_programmist
@dasha_programmist
ex Software Engineer at Reddit TS/React/GraphQL/Go

Почему может быть долгий fdatasync?

Есть приложение, которое использует boltdb в качестве key-value хранилища. Проблема в том, что при записи иногда (раз в несколько минут) проскакивают весьма "долгие" времена (100ms+), в то время как обычно 3-5ms. Запись внутри одной транзакции ведется небольшими порциями (~100 байт), причем постоянно ведется перезапись - увеличивается счетчик, сохранение на диск (то есть файл не расширяется, а изменяется). Запись производится с синхронизацией данных на диск (посмотрев в код библиотеки виден вызов fdatasync).
Особенность: данное поведение замечено при малых нагрузках (1-2 wr/5sec), при увеличении нагрузки (до 1-3 wr/sec) время стабилизируется.
Если говорить про качество диска - крутится все на виртуалке серии cx в hetzner.
Прикладываю пример лога (при выходе времени за 100ms вывожу tx.Stats() - это статистика транзакции в движке bolt, что дает понять узкое место)
2018/09/11 22:46:32 write op [1] -> db_time: 1.903964ms; all_time: 1.929144ms; count: 31102
2018/09/11 22:46:33 write op [1] -> db_time: 1.581177ms; all_time: 1.604657ms; count: 31103
2018/09/11 22:46:35 write op [1] -> db_time: 1.994612ms; all_time: 2.019831ms; count: 31104
2018/09/11 22:46:36 write op [1] -> db_time: 1.465624ms; all_time: 1.486556ms; count: 31105
2018/09/11 22:46:36 write op [1] -> db_time: 1.591314ms; all_time: 1.610906ms; count: 31106
2018/09/11 22:46:37 write op [1] -> db_time: 2.026614ms; all_time: 2.058671ms; count: 31107
2018/09/11 22:46:38 write op [1] -> db_time: 2.002381ms; all_time: 2.030729ms; count: 31108
2018/09/11 22:46:39 write op [1] -> db_time: 148.475589ms; all_time: 148.523364ms; count: 31109
2018/09/11 22:46:39 {PageCount:4 PageAlloc:16384 CursorCount:4 NodeCount:3 NodeDeref:0 Rebalance:0 RebalanceTime:0s Split:0 Spill:3 SpillTime:47.935µs Write:5 WriteTime:148.3063ms}
2018/09/11 22:46:40 write op [1] -> db_time: 2.154875ms; all_time: 2.180598ms; count: 31110
2018/09/11 22:46:42 write op [1] -> db_time: 1.889926ms; all_time: 1.919976ms; count: 31111
2018/09/11 22:46:42 write op [1] -> db_time: 1.620444ms; all_time: 1.64762ms; count: 31112
2018/09/11 22:46:42 write op [1] -> db_time: 2.231889ms; all_time: 2.266515ms; count: 31113
2018/09/11 22:46:45 write op [1] -> db_time: 1.964315ms; all_time: 1.982548ms; count: 31114
2018/09/11 22:46:45 write op [1] -> db_time: 2.211583ms; all_time: 2.227578ms; count: 31115
2018/09/11 22:46:47 write op [1] -> db_time: 2.087202ms; all_time: 2.141793ms; count: 31116
2018/09/11 22:46:48 write op [1] -> db_time: 1.777217ms; all_time: 1.791075ms; count: 31117
2018/09/11 22:46:49 write op [1] -> db_time: 1.604663ms; all_time: 1.620596ms; count: 31118
2018/09/11 22:46:49 write op [1] -> db_time: 1.929698ms; all_time: 1.953727ms; count: 31119
2018/09/11 22:46:50 write op [1] -> db_time: 2.098869ms; all_time: 2.123076ms; count: 31120
2018/09/11 22:46:52 write op [1] -> db_time: 2.335013ms; all_time: 2.355466ms; count: 31121
2018/09/11 22:46:53 write op [1] -> db_time: 1.846938ms; all_time: 1.876342ms; count: 31122
2018/09/11 22:46:54 write op [1] -> db_time: 1.897064ms; all_time: 1.922749ms; count: 31123
2018/09/11 22:46:55 write op [1] -> db_time: 1.804152ms; all_time: 1.829208ms; count: 31124
2018/09/11 22:46:57 write op [1] -> db_time: 2.354736ms; all_time: 2.380525ms; count: 31125
2018/09/11 22:46:59 write op [1] -> db_time: 1.975578ms; all_time: 2.043906ms; count: 31126
2018/09/11 22:46:59 write op [1] -> db_time: 1.639791ms; all_time: 1.665766ms; count: 31127
2018/09/11 22:47:00 write op [1] -> db_time: 35.765551ms; all_time: 35.799343ms; count: 31128
2018/09/11 22:47:02 write op [1] -> db_time: 1.789419ms; all_time: 1.815851ms; count: 31129
2018/09/11 22:47:02 write op [1] -> db_time: 1.684525ms; all_time: 1.711484ms; count: 31130
2018/09/11 22:47:03 write op [1] -> db_time: 1.828242ms; all_time: 1.847136ms; count: 31131
2018/09/11 22:47:05 write op [1] -> db_time: 2.129164ms; all_time: 2.159227ms; count: 31132
2018/09/11 22:47:07 write op [1] -> db_time: 2.292547ms; all_time: 2.324302ms; count: 31133
2018/09/11 22:47:08 write op [1] -> db_time: 1.750997ms; all_time: 1.776809ms; count: 31134
2018/09/11 22:47:09 write op [1] -> db_time: 2.146918ms; all_time: 2.168435ms; count: 31135
2018/09/11 22:47:10 write op [1] -> db_time: 2.037713ms; all_time: 2.064122ms; count: 31136
2018/09/11 22:47:11 write op [1] -> db_time: 1.936771ms; all_time: 1.962748ms; count: 31137
2018/09/11 22:47:11 write op [1] -> db_time: 1.70052ms; all_time: 1.72535ms; count: 31138
2018/09/11 22:47:11 write op [1] -> db_time: 2.138566ms; all_time: 2.163997ms; count: 31139
2018/09/11 22:47:12 write op [1] -> db_time: 1.735974ms; all_time: 1.769459ms; count: 31140
2018/09/11 22:47:14 write op [1] -> db_time: 2.271941ms; all_time: 2.287771ms; count: 31141
2018/09/11 22:47:14 write op [1] -> db_time: 1.961868ms; all_time: 2.012049ms; count: 31142
2018/09/11 22:47:14 write op [1] -> db_time: 3.009883ms; all_time: 3.044088ms; count: 31143
  • Вопрос задан
  • 206 просмотров
Решения вопроса 1
dasha_programmist
@dasha_programmist Автор вопроса
ex Software Engineer at Reddit TS/React/GraphQL/Go
Как сказал Пума Тайланд - провели тесты на реальном железе, после 30к запросов в течение 6-7 часов проблем не наблюдается, время записи стабильно.
Ответ написан
Пригласить эксперта
Ваш ответ на вопрос

Войдите, чтобы написать ответ

Войти через центр авторизации
Похожие вопросы