ignore long locked inactive cache entry

[Maxim Dounin]

Hello!

On Tue, Jul 31, 2018 at 02:03:47PM +0300, Иван wrote:

> Регулярно в логах (пару раз за 5 минут) вижу
> 
> [alert] 17816#17816: ignore long locked inactive cache entry
> 9100488b2180c1fc582384712a73791d, count:1
> 
> Две прокси на один бэкэнд. Бэкэнд - сервер nginx, отдающий статику.
> Прокси - два одинаковых сервера, в разных странах. Проявляется только на
> одном
> 
> Настроена зоне кеширования
> 
> proxy_cache_path /var/cache/nginx.hdd/archive_video levels=2:2
> keys_zone=a_v:10m inactive=2d max_size=145g use_temp_path=off;
> 
> 
> В локейшене:
> 
>                 proxy_buffer_size 128k;
>                 proxy_buffers 32 16k;
>                 proxy_set_header host backend;
> 
>                 proxy_cache_valid 2d;
> 
>                 proxy_cache_use_stale updating;
>                 proxy_cache_key "$proxy_host$uri$http_origin";
>                 proxy_cache_lock on;
> 
> 
> С чем может быть связано?
> 
> Локейшен обрабатывает не вебсокеты, а статические файлы. Раньше вроде не
> замечал, не помню когда начало появляться. Читал в поиске, что это может
> быть связано с медленными ответами, но не понял откуда и куда. Между
> прокси и бэкэндов - гигабит, в логах бэкэнда медленных ответов не
> увидел. На проксях медленных ответов (больше 5 секунд) сильно больше,
> чем сабжевых записей в логах, но это понятно, могут быть пользователи с
> медленными каналами.

Сообщение "ignore long locked inactive cache entry" означает, что, 
пытаясь удалить из кэша наиболее давно не использовавшийся 
элемент, nginx наткнулся на элемент, используемый в настоящий 
момент.  Такое сообщение может возникать:

- Из-за того, что запись пытаются удалить слишком быстро после 
  начала очередного запроса к ней.

Такое может быть при малых значениях inactive, max_size или 
недостаточном размере keys_zone.  В случае очистки по inactive и 
max_size сообщение будет от процесса cache manger'а, в случае 
keys_zone - от рабочих процессов, так что для начала проще всего 
посмотреть, что за процесс 17816 в сообщении выше.

- Из-за того, что какие-то рабочие процессы nginx'а падали (или 
  были завершены вручную), и оставили после себя некорректные 
  данные в разделяемой памяти кэша.

Информация о падениях есть на уровне alert в логе ошибок, его 
стоит почитать.  Если там что-то есть про падения рабочих 
процессов - для начала нужно разобраться с ними.

Сложнее с ручными завершениями по штатным сигналам - они 
логгируются на уровне notice, и если вдруг кто-то неосторожно 
посылает сигналы рабочим процессам - отследить это может быть 
непросто.  Так что проще всего убедиться, что после загрузки кэша 
заново (для этого подойдёт перезапуск nginx'а или процедура 
обновления исполняемого файла на лету aka upgrade) и вплодь до 
появления сообщений pid'ы рабочих процессов остаются те же самые.

- Из-за каких-либо ошибок, приводящих к утечке сокетов.

Были сигналы, что такое бывает при использовании HTTP/2, но пока 
неподтверждённые.  Ну и при использовании сторонних модулей такое 
также может быть легко, поэтому если вдруг используются сторонние 
модули - первым делом следует проверить, воспроизводится ли 
проблема без них.

Утечки сокетов правильнее всего диагностировать по сообщениям 
"open socket ... left in connection ..." на уровне alert при 
плавном завершении рабочих процессов.  Если процессы штатно 
завершаются без соответствующих сообщений - проблемы нет, если не 
завершаются вообще или при завершении в лог пишутся 
соответствующие ошибки - надо разбираться дальше.

-- 
Maxim Dounin
http://mdounin.ru/