Довольно много времени прошло после моей последней статьи про nginx под windows, неделя nginx закончилась. Стоит поправить это упущение.
Иногда так случается, что вдруг появилось свободное время, но для чего-то путного его не хватает, а простополазить в интернетах, почитать хабр всячески повышать свою квалификацию совсем не хочется.
Чтобы сделать все-таки что-нибудь полезного, решил заняться анализом логов с некоторых серверов одного проекта, насколько удастся впихнуть это в пару свободных минут.
После небольшого разбора и оценки в сравнении с результатами предыдущего анализа, заметил одну странность — абсолютная скорость отдачи nginx упала в среднем от 5 до 15%.
Объяснить, чем это вызвано с налета никак не удавалось, больших изменений вроде не было, объемы данных тоже настолько не выросли. Да и на отдаче динамики сильных изменений немного.
Покрутив логи и так и сяк, зацепился за отдачу маленькой статики — выяснилась одна закономерность: чем длиннее путь (url) — тем «медлительней» становился nginx (независимо от размера файла).
Итак после нескольких экспериментов, имеем следующие факты:
И тут пришло озарение — я вспомнил, что в этом проекте изменилась файловая структура, и вложенность до некоторой статики и динамики, отдаваемой файлом (по redirect), увеличилась на два-три, а местами до пяти каталогов.
Компилировать debug-версию под профайлер-анализатор было лень, будем искать «дедуктивным» способом.
Измеряем с помощью siege среднюю скорость отдачи «test.gif» — порядка 5500 rps (nginx 4 workers, concurency 15).
Создаем тестовый location с root «D:\...\ms\ms\ms\ms\ms\ms\ms\ms», где сегмент пути ms повторяется 60 раз и запрашиваем URL «test-loc/test.gif».
Снова измеряем среднюю скорость отдачи — уже 900 rps.
Возможно это что-то где-то на уровне проверки легальности пути. Пробуем замерить 404 для несуществующего файла с URL «test-loc/test-file-not-exists.gif» — скорость вырастает до 13167 rps и что странно вложенность пути уже не имеет значения.
Включаем дебаг в логгировании nginx, и затем детально анализируем логи в сравнении малая — большая вложенность пути. В среднем время от «http request line» до «http filename» одинаково, но запись «http static fd» для длинного пути уже ощутимо отстает.
Довольно странно, поэтому пытаемся проверить что происходит, используя процесс-мониторинг.
Причем на каждый запрос это наблюдается дважды, вероятно один раз при открытии, второй раз при чтении атрибутов файла.
Лезем в исходники nginx, довольно быстро находим в
Эту же функцию
Сперва идет проверка правильности пути сегментов, исключения NTFS streams (":"), точек и пробелов в конце и т.д. Но в этом теле цикла проверкой не осуществляются никакие системные вызовы.
Идем дальше и видим вызов GetLongPathNameW в блоке, проверяющем длинное имя файла.
Для пробы закомментируем эту проверку, компилируем nginx — в результате имеем 9100 rps, там где ранее nginx отдавал 900 rps.
Видимо Максим когда делал эту проверку не знал (ваш покорный слуга кстати тоже), что Windows возвращает длинное имя файла рекурсивно, т.е. для каждого подкаталога (и как видим эта информация не кэшируется в OS).
К сожалению, таким образом (т.е. полностью) не стоит убирать эту проверку, чтобы исключить доступ к файлам по коротким именам 8.3 (вида «testpa~1/testfi~2.gif»), а лучшей функции делающей тоже самое, я к сожалению не знаю.
Однако можно добавить выше установку специального флажка, проверкой существования символа "~", только при наличии которого мы и будем осуществлять проверку длинного пути, вызывая
В результате при минимальных изменениях имеем рост скорости от 2 до 10 раз (зависит от вложенности и размеров файла) и в разы меньшую нагрузку на дисковую подсистему.
Ну и как обычно сравнения производительности, до (первый и третий столбцы помечены **NF) и после.
Первые два — для короткого (12 сегментов) пути.
Следующие два — для длинного (55 сегментов) пути.
Измерение siege (concurency: 15), win7 — i5-2400 cpu @ 3.10GHz (4 core), gif-статика: 452 байт (+ header), 4 воркера nginx.
У себя в branch nginx-mod я уже интегрировал этот этот PR.
Будет время, сделаю changeset для оригинального hg-репозитария и отправлю CR в nginx-dev.
Иногда так случается, что вдруг появилось свободное время, но для чего-то путного его не хватает, а просто
Чтобы сделать все-таки что-нибудь полезного, решил заняться анализом логов с некоторых серверов одного проекта, насколько удастся впихнуть это в пару свободных минут.
После небольшого разбора и оценки в сравнении с результатами предыдущего анализа, заметил одну странность — абсолютная скорость отдачи nginx упала в среднем от 5 до 15%.
Объяснить, чем это вызвано с налета никак не удавалось, больших изменений вроде не было, объемы данных тоже настолько не выросли. Да и на отдаче динамики сильных изменений немного.
Покрутив логи и так и сяк, зацепился за отдачу маленькой статики — выяснилась одна закономерность: чем длиннее путь (url) — тем «медлительней» становился nginx (независимо от размера файла).
Итак после нескольких экспериментов, имеем следующие факты:
- скорость отдачи падает прямо пропорционально увеличению длины пути до файла
- скорость практически не зависит от длинны URL, т.е. если URL короткий, но увеличиваем длину root/alias, скорость отдачи падает также, т.е. это все-таки длинна пути, а не URL
- ну и наконец, поиграв с путями файла, а именно его вложенности, выяснилось, что скорость отдачи падает в зависимости от количества поддиректорий, и не зависит от длины как-таковой. Т.е. файл «D:\...\ms-ms-ms-ms-ms-ms-ms-ms\test.gif» отдается много быстрее «D:\...\ms\ms\ms\ms\ms\ms\ms\ms\test.gif»
И тут пришло озарение — я вспомнил, что в этом проекте изменилась файловая структура, и вложенность до некоторой статики и динамики, отдаваемой файлом (по redirect), увеличилась на два-три, а местами до пяти каталогов.
Компилировать debug-версию под профайлер-анализатор было лень, будем искать «дедуктивным» способом.
Измеряем с помощью siege среднюю скорость отдачи «test.gif» — порядка 5500 rps (nginx 4 workers, concurency 15).
Создаем тестовый location с root «D:\...\ms\ms\ms\ms\ms\ms\ms\ms», где сегмент пути ms повторяется 60 раз и запрашиваем URL «test-loc/test.gif».
Снова измеряем среднюю скорость отдачи — уже 900 rps.
Возможно это что-то где-то на уровне проверки легальности пути. Пробуем замерить 404 для несуществующего файла с URL «test-loc/test-file-not-exists.gif» — скорость вырастает до 13167 rps и что странно вложенность пути уже не имеет значения.
Включаем дебаг в логгировании nginx, и затем детально анализируем логи в сравнении малая — большая вложенность пути. В среднем время от «http request line» до «http filename» одинаково, но запись «http static fd» для длинного пути уже ощутимо отстает.
Довольно странно, поэтому пытаемся проверить что происходит, используя процесс-мониторинг.
Под спойлером имеем следующую картину
15:23:43,2205361 nginx.exe 9780 CreateFile D:\ SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2206208 nginx.exe 9780 QueryDirectory D:\Projects SUCCESS Filter: Projects, 1: Projects
15:23:43,2206430 nginx.exe 9780 CloseFile D:\ SUCCESS
15:23:43,2207337 nginx.exe 9780 CreateFile D:\Projects SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2207844 nginx.exe 9780 QueryDirectory D:\Projects\app_srv SUCCESS Filter: app_srv, 1: app_srv
15:23:43,2208009 nginx.exe 9780 CloseFile D:\Projects SUCCESS
15:23:43,2208728 nginx.exe 9780 CreateFile D:\Projects\app_srv SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2209238 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp SUCCESS Filter: tmp, 1: tmp
15:23:43,2209383 nginx.exe 9780 CloseFile D:\Projects\app_srv SUCCESS
15:23:43,2210075 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2210615 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms SUCCESS Filter: ms, 1: ms
15:23:43,2210764 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp SUCCESS
15:23:43,2211466 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2211995 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2212141 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms SUCCESS
15:23:43,2212813 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2213326 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2213462 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms SUCCESS
15:23:43,2214193 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2214677 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2214806 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms SUCCESS
# ... 106 lines ... #
15:23:43,2265328 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2265851 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2265980 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2266665 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2267165 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2267291 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2267976 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2268489 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2268622 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2269314 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2269814 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2269946 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2270615 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2271135 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2271264 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2271989 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2272525 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2272654 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2273343 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2273876 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2274005 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2274743 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2275246 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2275375 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2276034 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2276531 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2276657 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2277332 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
15:23:43,2277819 nginx.exe 9780 QueryDirectory D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS Filter: ms, 1: ms
15:23:43,2277944 nginx.exe 9780 CloseFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms SUCCESS
15:23:43,2278987 nginx.exe 9780 CreateFile D:\Projects\app_srv\tmp\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\ms\test.gif SUCCESS Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
Причем на каждый запрос это наблюдается дважды, вероятно один раз при открытии, второй раз при чтении атрибутов файла.
Лезем в исходники nginx, довольно быстро находим в
[src]\os\win32\ngx_files.c
функцию ngx_open_file
, которая только в случае успешного открытия файла (а мы помним про быстрый 404), вызывает другую функцию ngx_win32_check_filename
(проверка легальности имени файла).Эту же функцию
ngx_win32_check_filename
вызывает и другая функция ngx_file_info
. Ну и рассмотрим под лупой наш кандидат на роль «ручного тормоза».Сперва идет проверка правильности пути сегментов, исключения NTFS streams (":"), точек и пробелов в конце и т.д. Но в этом теле цикла проверкой не осуществляются никакие системные вызовы.
Идем дальше и видим вызов GetLongPathNameW в блоке, проверяющем длинное имя файла.
Для пробы закомментируем эту проверку, компилируем nginx — в результате имеем 9100 rps, там где ранее nginx отдавал 900 rps.
Видимо Максим когда делал эту проверку не знал (ваш покорный слуга кстати тоже), что Windows возвращает длинное имя файла рекурсивно, т.е. для каждого подкаталога (и как видим эта информация не кэшируется в OS).
К сожалению, таким образом (т.е. полностью) не стоит убирать эту проверку, чтобы исключить доступ к файлам по коротким именам 8.3 (вида «testpa~1/testfi~2.gif»), а лучшей функции делающей тоже самое, я к сожалению не знаю.
Однако можно добавить выше установку специального флажка, проверкой существования символа "~", только при наличии которого мы и будем осуществлять проверку длинного пути, вызывая
GetLongPathNameW
.В результате при минимальных изменениях имеем рост скорости от 2 до 10 раз (зависит от вложенности и размеров файла) и в разы меньшую нагрузку на дисковую подсистему.
Ну и как обычно сравнения производительности, до (первый и третий столбцы помечены **NF) и после.
Первые два — для короткого (12 сегментов) пути.
Следующие два — для длинного (55 сегментов) пути.
Path, Segments | Short, 12 **NF | Short, 12 | Long, 55 **NF | Long, 55 |
---|---|---|---|---|
Transactions | 16732 hits | 28380 hits | 2962 hits | 26820 hits |
Availability | 100.00 % | 100.00 % | 100.00 % | 100.00 % |
Elapsed time | 2.96 secs | 2.96 secs | 2.97 secs | 2.97 secs |
Data transferred | 7.21 MB | 12.23 MB | 1.28 MB | 11.56 MB |
Response time | 0.00 secs | 0.00 secs | 0.00 secs | 0.00 secs |
Transaction rate | 5645.07 trans/sec | 9591.08 trans/sec | 996.04 trans/sec | 9030.30 trans/sec |
Throughput | 2.43 MB/sec | 4.13 MB/sec | 0.44 MB/sec | 3.89 MB/sec |
Concurrency | 14.92 | 14.72 | 14.80 | 14.12 |
Successful transactions | 16732 | 28380 | 2962 | 26820 |
Failed transactions | 0 | 0 | 0 | 0 |
Longest transaction | 0.11 | 0.11 | 0.12 | 0.12 |
Shortest transaction | 0.00 | 0.00 | 0.00 | 0.00 |
У себя в branch nginx-mod я уже интегрировал этот этот PR.
Будет время, сделаю changeset для оригинального hg-репозитария и отправлю CR в nginx-dev.