Почему может быть долгий 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
Читать дальше
Особенность: данное поведение замечено при малых нагрузках (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