Есть приложение, которое использует 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