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.alex@gmail.com> написал:
>
>>
>>
>> 25 сентября 2015 г., 17:21 пользователь Иван Мишин <simplebox66@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 <andrey@kopeyko.ru>_______________________________________________
nginx-ru mailing list
nginx-ru@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-ru