On Fri, 25 Sep 2015, Иван Мишин wrote:
Добрый вечер, Иван!
4.200 3.500 и т.д. это и есть время ответа от бека.
и например вот тут
www.site.ru x.x.x.x - [23/Jul/2015:15:15:14 +0300] "GET /a/b HTTP/1.1"
4.100 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:15:15:15 +0300] "GET /a/b HTTP/1.1"
0.000 " NGINX-CACHE-HIT
бек обрабатывал 4.100 как видно но следующий запрос уже через 1 сек получил
HIT не смотря на то что по идеи первый запрос еще в кеш не попал
Никакой неадекватности в работе кеша нет - вы просто не учитываете (или
позабыли) тот факт, что время в лог пишется ровно в момент логирования -
т.е. _по_окончании_ запроса.
Такое поведение nginx унаследовал от Apache.
В документации этот момент отражён, но вскользь - только при описании
переменной "$msec"
http://nginx.org/ru/docs/http/ngx_http_log_module.html#log_format
Поэтому ваши логи показывают, что всё происходит ровно как вами и было
задумано:
- запрос пришёл в ~ 15:15:09.900
- бэкенд обработал его за 4.100 сек и в 15:15:14 была создана запись в
логе
- следующий запрос пришёл в 15:15:15 и был отдан из кеша.
P.S.
Наверное, стОит расширить\дополнить описание модуля ngx_http_log, и ещё
раз явно указать момент логирования при описании переменных
- $time_iso8601
- $time_local
Хуже, по крайней мере, точно не будет.
25 сентября 2015 г., 18:54 пользователь Aleksandr Sytar <
sytar.a...@gmail.com> написал:
25 сентября 2015 г., 17:21 пользователь Иван Мишин <simplebo...@gmail.com>
написал:
Кеш заведен на 20 минут при этом иногда бывает что кеш как-бы не
срабатывает.
Ключи кеша proxy_cache_key $server_name$request_uri
Вот пример из логов адекватной работы:
www.site.ru x.x.x.x - [23/Jul/2015:11:02:32 +0300] "GET /a/b HTTP/1.1"
4.200 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:11:02:44 +0300] "GET /a/b HTTP/1.1"
0.000 " NGINX-CACHE-HIT
www.site.ru x.x.x.x - [23/Jul/2015:13:11:02 +0300] "GET /a/b HTTP/1.1"
4.200 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:13:11:02 +0300] "GET /a/b HTTP/1.1"
0.000 " NGINX-CACHE-HIT
www.site.ru x.x.x.x - [23/Jul/2015:15:15:14 +0300] "GET /a/b HTTP/1.1"
4.100 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:15:15:15 +0300] "GET /a/b HTTP/1.1"
0.000 " NGINX-CACHE-HIT
А вот пример неадекватной работы:
www.site.ru x.x.x.x - [23/Jul/2015:11:15:41 +0300] "GET /a/b HTTP/1.1"
4.000 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:11:15:46 +0300] "GET /a/b HTTP/1.1"
4.200 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:12:57:34 +0300] "GET /a/b HTTP/1.1"
3.500 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:12:57:38 +0300] "GET /a/b HTTP/1.1"
4.100 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:17:42:33 +0300] "GET /a/b HTTP/1.1"
3.600 " NGINX-CACHE-EXPIRED
www.site.ru x.x.x.x - [23/Jul/2015:17:42:38 +0300] "GET /a/b HTTP/1.1"
4.100 " NGINX-CACHE-EXPIRED
Куда копать?
Добавить логгирование времени ответа бекенеда и понять успевает ли он
ответить за 5 секунд
_______________________________________________
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru
--
Best regards,
Andrey Kopeyko <and...@kopeyko.ru>
_______________________________________________
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru
