Re: unit зависает с php 7.4 (nginx+unit+nextcloud на debian 11)
Иван
nginx at kinetiksoft.com
Sun Mar 20 16:44:42 UTC 2022
Здравствуйте!
На unit 1.25 - не было ни одного "зависания" за несколько дней.
Вчера обновились до 1.26.1 и поставили фиксированное количество
процессов - 20, только за текущие сутки уже два зависания. Написал на
баше вотчог, который перезапускает unit, если тот перестаёт отвечать по
http. Готовы пробовать другие идеи, как мы можем помочь в поимке бага.
Пишем дебаг-лог, но он, естественно, очень большой (за сутки порядка
единиц гигабайт в несжатом виде)+содержит конфиденциальные данные, если
он нужен, скажите, куда я могу приватно скинуть на него ссылку.
С уважением, Иван.
14.03.2022 16:21, Max Romanov пишет:
> В самом деле, "Resource temporarily unavailable" - это безобидное
> сообщение. LimitNOFILE можно убирать :)
>
> Тогда предположение такое - ошибка (гонка) при остановке "idle"
> процессов. Как закончите эксперимент с 1.25 (результат интересен!),
> попробуйте зафиксировать кол-во процессов (напр. "processes": 10).
>
> —
> Max
>
>
>> On 14 Mar 2022, at 11:52, Иван <nginx at kinetiksoft.com> wrote:
>>
>> Здравствуйте!
>>
>> Поменяли вот так (для НЕдебаг так же):
>>
>>
>>> # cat /etc/systemd/system/unit-debug.service.d/limits.conf
>>> [Service]
>>> LimitNOFILE=100000
>>> LimitCORE=infinity
>>
>>
>>
>>> # ps ax | grep -E 'unit.*router*'
>>> 2975112 ? Sl 0:08 unit: router
>>
>>
>>> cat /proc/2975112/limits | grep 'Max open files'
>>> Max open files 100000 100000 files
>>
>> Во время зависания мониторили как lsof ... | grep TCP, так и grep -v
>> TCP так и просто, без grep. Даже близко к 100 тысяч не приближалось.
>> На текущий момент предположили, что, в связи с серьезными изменениями
>> в 1.26 в части пыхи, там ошибка в коде и откатились на 1.25. Пока без
>> проблем, но и откатились недавно. Если скажете более конкретно какую
>> информацию собирать, можем еще раз попробовать с 1.26.1 (если на 1.25
>> проблем не будет).
>>
>> С уважением, Иван.
>>
>> 14.03.2022 10:00, Max Romanov пишет:
>>> Здравствуйте, Иван.
>>>
>>> Похоже, что процессу 'unit: router' (pid 244884) не хватает файловых дескрипторов для принятия очередного клиентского соединения.
>>>
>>> Чтобы убедиться, что это так, можно посчитать кол-во используемых дескрипторов (напр. 'lsof -p 244884') и сравнить со значениями в строке 'Max open files' в /proc/244884/limits .
>>>
>>> Если кол-во дескрипторов маленькое на фоне 'Resource temporarily unavailable', то предположение неверное.
>>> Если кол-во дескрипторов большое, но существенно отличается от количества подключений, надо искать утечку дескрипторов в роутере (возможно, ошибка в Unit).
>>>
>>> Если кол-во используемых дескрипторов близко к предельному и (примерно) соответствует количеству клиентских соединений, то необходимо увеличить лимит.
>>>
>>>> Мы уже выставили ему NoFiles = 10000, пробуем поставить 100000 и перенести сессии php в редис, может что-то еще не учли?
>>>>
>>> Направление похожее, но я не понял _где_ это выставлено. Повиляло ли это на /proc/<router pid>/limits ? Если нет - значит не та (или не там) настройка.
>>>
>>> —
>>> Max
>>>
>>>> On 11 Mar 2022, at 11:58, Иван<nginx at kinetiksoft.com> wrote:
>>>>
>>>> Здравствуйте!
>>>>
>>>>
>>>> Перевели nextcloud (php) на unit. Периодически unit полностью перестаёт отвечать на запросы. В этот момент запрос к любому урлу с application nextcloud , обламывается по timeout. В логах nginx соотвественно
>>>>
>>>> 2022/03/11 10:48:37 [error] 156145#156145: *43083 upstream timed out (110: Connection timed out) while reading response header from upstre
>>>> am, client: 46.55, server:c.com <http://c.com>, request: "GET /thecloud/ocs/v2.php/apps/activity/api/v2/activity?since=1883732&li
>>>> mit=50&format=json HTTP/1.1", upstream:"http://127.0.0.1:8000/thecloud/ocs/v2.php/apps/activity/api/v2/activity?since=1883732&limit=50&fo
>>>> rmat=json", host: "c.com <http://c.com>"
>>>>
>>>> В логах unit вообще смущает
>>>>
>>>>> grep -c 'Resource temporarily unavailable' /var/log/unit.log
>>>>> 94542
>>>> Мы уже выставили ему NoFiles = 10000, пробуем поставить 100000 и перенести сессии php в редис, может что-то еще не учли?
>>>>
>>>> Дебаг-логи юнита включили, но ничего соотвествующего проблеме не увидели. Например, приведенное выше сообщение в логах nginx - первое за сегодня. Кусок лога unit за это время:
>>>>
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 h1p body rest: 0
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 http application handler
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 rpc: stream #23217 registered
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 mp 7F0600049E30 retain: 2
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 pthread_mutex_lock(55E27D377000) enter
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 pthread_mutex_unlock(55E27D377000) exit
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 mp 7F0600049E30 retain: 3
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 request 1345 bytes shm buffer
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 mp 7F0600000BB0 retain: 25
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 pthread_mutex_lock(55E27D377138) enter
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 pthread_mutex_unlock(55E27D377138) exit
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 outgoing mmap buf allocation: 7F0600028600 [7F06091F5000,16384] 244884->0,0,24
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 fields_count=13
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0xE6EB, 0, 4, 7F0600049171 : 21 7F0600049177
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x7F29, 0, 15, 7F060004918E : 12 7F060004919F
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x25AB, 0, 10, 7F06000491AD : 5 7F06000491B9
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x1EA0, 0, 14, 7F06000491C0 : 3 7F06000491D0
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0xA841, 0, 5, 7F06000491D5 : 1 7F06000491DC
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0xB29A, 0, 13, 7F06000491DF : 42 7F06000491EE
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x0220, 0, 10, 7F060004921A : 145 7F0600049226
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0xD871, 0, 6, 7F06000492B9 : 3 7F06000492C1
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x5F7D, 0, 12, 7F06000492C6 : 23 7F06000492D4
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0xEDFF, 0, 12, 7F06000492ED : 36 7F06000492FB
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x23F2, 0, 6, 7F0600049321 : 277 7F0600049329
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0x9683, 0, 15, 7F0600049440 : 13 7F0600049451
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 add field 0xEA97, 0, 15, 7F0600049460 : 10 7F0600049471
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 about to send 1345 bytes buffer to app process port 12
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 *22759 queue is not empty
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 timer found minimum: 313989843±50:313748980
>>>>> 2022/03/11 10:48:36.250 [debug] 244884#244901 epoll_wait(36) timeout:240863
>>>>> 2022/03/11 10:48:37.114 [debug] 244884#244901 epoll_wait(36): 1
>>>>> 2022/03/11 10:48:37.114 [debug] 244884#244901 *22733 epoll: fd:17 ev:2001 d:7F060001D390 rd:2 wr:0
>>>>> 2022/03/11 10:48:37.114 [debug] 244884#244901 timer expire minimum: 313989793:313749844
>>>>> 2022/03/11 10:48:37.114 [debug] 244884#244901 timer found minimum: 313989843±50:313749844
>>>>> 2022/03/11 10:48:37.114 [debug] 244884#244901 epoll_wait(36) timeout:239999
>>>>> 2022/03/11 10:48:37.146 [debug] 244884#244901 epoll_wait(36): 1
>>>>> 2022/03/11 10:48:37.146 [debug] 244884#244901 *22735 epoll: fd:19 ev:2001 d:7F06000029C0 rd:2 wr:0
>>>>> 2022/03/11 10:48:37.146 [debug] 244884#244901 timer expire minimum: 313989793:313749876
>>>>> 2022/03/11 10:48:37.146 [debug] 244884#244901 timer found minimum: 313989843±50:313749876
>>>>> 2022/03/11 10:48:37.146 [debug] 244884#244901 epoll_wait(36) timeout:239967
>>>>> 2022/03/11 10:48:37.190 [debug] 244884#244901 epoll_wait(36): 1
>>>>> 2022/03/11 10:48:37.190 [debug] 244884#244901 *22736 epoll: fd:20 ev:2001 d:7F060000F710 rd:2 wr:0
>>>>> 2022/03/11 10:48:37.190 [debug] 244884#244901 timer expire minimum: 313989793:313749920
>>>>> 2022/03/11 10:48:37.190 [debug] 244884#244901 timer found minimum: 313989843±50:313749920
>>>>> 2022/03/11 10:48:37.190 [debug] 244884#244901 epoll_wait(36) timeout:239923
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 epoll_wait(36): 1
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 epoll: fd:14 ev:0001 d:7F0600001430 rd:5 wr:0
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 timer expire minimum: 313989793:313756676
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 work queue: accept
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 accept4(14): 102
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 client: 127.0.0.1
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 malloc(168): 7F0600005F70
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 posix_memalign(16, 464): 7F060004B2E0
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 *22761 connections: 26
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 work queue: accept
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 accept4(14) (11: Resource temporarily unavailable)
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 work queue: read
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 *22760 http conn init
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 work queue: read
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 *22760 conn read fd:102 rdy:0 cl:0 er:0 bl:0
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 *22760 epoll 36 set event: fd:102 op:1 ev:80002001
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 *22760 timer add: 0±50 180000:313936676
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 *22760 timer change: 313936676±50:1
>>>>> 2022/03/11 10:48:43.946 [debug] 244884#244901 timers changes: 1
>>>> Конфиг unit'а:
>>>>
>>>>> {
>>>>> "settings": {
>>>>> "http": {
>>>>> "max_body_size": 10737418240,
>>>>> "body_read_timeout": 3600
>>>>> }
>>>>> },
>>>>> "listeners": {
>>>>> "127.0.0.1:8000": {
>>>>> "pass": "routes",
>>>>> "client_ip": {
>>>>> "header": "X-Forwarded-For",
>>>>> "source": [
>>>>> "127.0.0.1"
>>>>> ]
>>>>> }
>>>>> }
>>>>> },
>>>>>
>>>>> "routes": [
>>>>> {
>>>>> "match": {
>>>>> "uri": [
>>>>> "/thecloud/core/ajax/update.php*",
>>>>> "/thecloud/cron.php*",
>>>>> "/thecloud/index.php*",
>>>>> "/thecloud/ocm-provider*.php*",
>>>>> "/thecloud/ocs-provider*.php*",
>>>>> "/thecloud/ocs/v1.php*",
>>>>> "/thecloud/ocs/v2.php*",
>>>>> "/thecloud/public.php*",
>>>>> "/thecloud/remote.php*",
>>>>> "/thecloud/status.php*",
>>>>> "/thecloud/updater*.php*"
>>>>> ]
>>>>> },
>>>>>
>>>>> "action": {
>>>>> "pass": "applications/nextcloud/direct"
>>>>> }
>>>>> },
>>>>> {
>>>>> "match": {
>>>>> "uri": "/thecloud/ocm-provider*"
>>>>> },
>>>>>
>>>>> "action": {
>>>>> "pass": "applications/nextcloud/ocm"
>>>>> }
>>>>> },
>>>>> {
>>>>> "match": {
>>>>> "uri": "/thecloud/ocs-provider*"
>>>>> },
>>>>>
>>>>> "action": {
>>>>> "pass": "applications/nextcloud/ocs"
>>>>> }
>>>>> },
>>>>> {
>>>>> "match": {
>>>>> "uri": "/thecloud/updater*"
>>>>> },
>>>>>
>>>>> "action": {
>>>>> "pass": "applications/nextcloud/updater"
>>>>> }
>>>>> },
>>>>> {
>>>>> "match": {
>>>>> "uri": "/thecloud/*"
>>>>> },
>>>>> "action": {
>>>>> "share": "/usr/local$uri",
>>>>> "fallback": {
>>>>> "pass": "applications/nextcloud/index"
>>>>> }
>>>>> }
>>>>> },
>>>>> {
>>>>> "action": {
>>>>> "return": 403
>>>>> }
>>>>> }
>>>>> ],
>>>>>
>>>>> "applications": {
>>>>> "nextcloud": {
>>>>> "user": "php-nextcloud",
>>>>> "group": "php-nextcloud",
>>>>> "limits": {
>>>>> "timeout": 300,
>>>>> "requests": 10000
>>>>> },
>>>>> "processes": {
>>>>> "max": 20,
>>>>> "spare": 10,
>>>>> "idle_timeout": 300
>>>>> },
>>>>> "options": {
>>>>> "admin": {
>>>>> "memory_limit": "512M",
>>>>> "post_max_size": "10G",
>>>>> "upload_max_filesize": "10G",
>>>>> "max_execution_time": "3600",
>>>>> "max_input_time": "3600"
>>>>> }
>>>>> },
>>>>> "type": "php",
>>>>> "targets": {
>>>>> "direct": {
>>>>> "root": "/usr/local/"
>>>>> },
>>>>>
>>>>> "index": {
>>>>> "root": "/usr/local/nextcloud/",
>>>>> "script": "index.php"
>>>>> },
>>>>>
>>>>> "ocm": {
>>>>> "root": "/usr/local/nextcloud/ocm-provider/",
>>>>> "script": "index.php"
>>>>> },
>>>>>
>>>>> "ocs": {
>>>>> "root": "/usr/local/nextcloud/ocs-provider/",
>>>>> "script": "index.php"
>>>>> },
>>>>>
>>>>> "updater": {
>>>>> "root": "/usr/local/nextcloud/updater/",
>>>>> "script": "index.php"
>>>>> }
>>>>> }
>>>>> }
>>>>> }
>>>>> }
>>>> Заранее спасибо!
>>>>
>>>>
>>>> С уважением, Иван.
>>>>
>>>> _______________________________________________
>>>> unit mailing list --unit at nginx.org
>>>> To unsubscribe send an email tounit-leave at nginx.org
>>> _______________________________________________
>>> unit mailing list --unit at nginx.org
>>> To unsubscribe send an email tounit-leave at nginx.org
>> _______________________________________________
>> unit mailing list -- unit at nginx.org
>> To unsubscribe send an email to unit-leave at nginx.org
>
>
> _______________________________________________
> unit mailing list --unit at nginx.org
> To unsubscribe send an email tounit-leave at nginx.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/unit/attachments/20220320/d834ecbe/attachment.htm>
More information about the unit
mailing list