Gearman escrevendo “Muitos arquivos abertos” no log. Problemas de espaço em disco

2

Estamos executando um serviço que faz capturas de tela do URL fornecido e as publica em nosso bucket do S3. Semelhante ao manet , mas nosso aplicativo nodejs codificado personalizado. Não armazenamos as capturas de tela em nosso disco rígido local. Nós os armazenamos temporariamente para redimensionar e, em seguida, excluir. A pasta da imagem temporária está sempre vazia.

O problema é: o espaço em disco está sendo executado cada vez mais baixo até a reinicialização do servidor. Por exemplo, agora df -h mostra:

ubuntu@ip-10-0-1-94:~$ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      118G   74G   40G  65% /
none            4.0K     0  4.0K   0% /sys/fs/cgroup
udev            7.4G  8.0K  7.4G   1% /dev
tmpfs           1.5G  360K  1.5G   1% /run
none            5.0M     0  5.0M   0% /run/lock
none            7.4G     0  7.4G   0% /run/shm
none            100M     0  100M   0% /run/user

No entanto, du -sh / mostra:

root@ip-10-0-1-94:~# du -sh /
du: cannot access ‘/proc/14440’: No such file or directory
du: cannot access ‘/proc/14520/task/14520/fd/4’: No such file or directory
du: cannot access ‘/proc/14520/task/14520/fdinfo/4’: No such file or directory
du: cannot access ‘/proc/14520/fd/4’: No such file or directory
du: cannot access ‘/proc/14520/fdinfo/4’: No such file or directory
du: cannot access ‘/proc/14521’: No such file or directory
7.0G    /

Se eu fizer du para todas as pastas no sistema de arquivos raiz, ele será de até 7 Gb, não 74. Se eu reiniciar o servidor, quando o backup for feito novamente, haverá 7 Gb como deveria, mas em 10-12 horas 70+ novamente e contando.

Estamos usando mongodb como nosso armazenamento, por isso estou assumindo que pode ser, mas removi a opção smallfiles config que coloquei anteriormente. Ainda é a mesma coisa.

Anexando lsof output aqui e ps aux aqui

Aqui está o mount output:

ubuntu@ip-10-0-1-94:~$ mount
/dev/xvda1 on / type ext4 (rw,discard)
proc on /proc type proc (rw,noexec,nosuid,nodev)
sysfs on /sys type sysfs (rw,noexec,nosuid,nodev)
none on /sys/fs/cgroup type tmpfs (rw)
none on /sys/fs/fuse/connections type fusectl (rw)
none on /sys/kernel/debug type debugfs (rw)
none on /sys/kernel/security type securityfs (rw)
udev on /dev type devtmpfs (rw,mode=0755)
devpts on /dev/pts type devpts (rw,noexec,nosuid,gid=5,mode=0620)
tmpfs on /run type tmpfs (rw,noexec,nosuid,size=10%,mode=0755)
none on /run/lock type tmpfs (rw,noexec,nosuid,nodev,size=5242880)
none on /run/shm type tmpfs (rw,nosuid,nodev)
none on /run/user type tmpfs (rw,noexec,nosuid,nodev,size=104857600,mode=0755)
none on /sys/fs/pstore type pstore (rw)
systemd on /sys/fs/cgroup/systemd type cgroup (rw,noexec,nosuid,nodev,none,name=systemd)

Reiniciar os serviços em execução, como mongodb ou supervisor , não altera nada. Aqui está um exemplo:

root@ip-10-0-1-94:~# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      118G   74G   40G  65% /
none            4.0K     0  4.0K   0% /sys/fs/cgroup
udev            7.4G  8.0K  7.4G   1% /dev
tmpfs           1.5G  360K  1.5G   1% /run
none            5.0M     0  5.0M   0% /run/lock
none            7.4G     0  7.4G   0% /run/shm
none            100M     0  100M   0% /run/user
root@ip-10-0-1-94:~# service mongod restart
mongod stop/waiting
mongod start/running, process 31590
root@ip-10-0-1-94:~# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      118G   74G   40G  65% /
none            4.0K     0  4.0K   0% /sys/fs/cgroup
udev            7.4G  8.0K  7.4G   1% /dev
tmpfs           1.5G  360K  1.5G   1% /run
none            5.0M     0  5.0M   0% /run/lock
none            7.4G     0  7.4G   0% /run/shm
none            100M     0  100M   0% /run/user

ou supervisor controlando node process (trabalhadores e aplicativo):

root@ip-10-0-1-94:~# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      118G   74G   40G  65% /
none            4.0K     0  4.0K   0% /sys/fs/cgroup
udev            7.4G  8.0K  7.4G   1% /dev
tmpfs           1.5G  360K  1.5G   1% /run
none            5.0M     0  5.0M   0% /run/lock
none            7.4G     0  7.4G   0% /run/shm
none            100M     0  100M   0% /run/user
root@ip-10-0-1-94:~# service supervisor restart
Restarting supervisor: supervisord.
root@ip-10-0-1-94:~# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/xvda1      118G   74G   40G  65% /
none            4.0K     0  4.0K   0% /sys/fs/cgroup
udev            7.4G  8.0K  7.4G   1% /dev
tmpfs           1.5G  360K  1.5G   1% /run
none            5.0M     0  5.0M   0% /run/lock
none            7.4G     0  7.4G   0% /run/shm
none            100M     0  100M   0% /run/user

UPDATE : acontece que isso acontece por causa do gearman log com toneladas de

accept(Too many open files) -> libgearman-server/gearmand.cc:851

mensagens. Mesmo que o arquivo seja excluído, ele ainda é aberto pelos processos do gearman e, portanto, o espaço não é liberado. Esta é a prova:

root@ip-10-0-1-94:~# sudo lsof -s | awk '$5 == "REG"' | sort -n -r -k 7,7 | head -n 1
gearmand   4221           gearman    3w      REG              202,1 31748949650     143608 /var/log/gearman-job-server/gearman.log.1 (deleted)

(graças a @Andrew Henle)

Agora, a próxima pergunta é: por que gearman escreve isso no log. Conforme declarado aqui , isso ocorre devido a muitas conexões com gearman em TIME_WAIT state No entanto, eles não estão em TIME_WAIT , eles estão em ESTABLISHED . Aqui eles estão.

Se eu fizer strace -p 4221 , só vejo isso

write(22, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169649, 568914324}) = 0
gettimeofday({1446109467, 793708}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33010), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 874
write(17, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169659, 749954206}) = 0
gettimeofday({1446109477, 974726}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33060), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 875
write(32, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169659, 754505349}) = 0
gettimeofday({1446109477, 979307}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33062), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 876
write(27, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169664, 300399805}) = 0
gettimeofday({1446109482, 525209}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33134), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 877
write(22, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169666, 161035104}) = 0
gettimeofday({1446109484, 385826}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33165), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 878
write(17, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169668, 308112847}) = 0
gettimeofday({1446109486, 532900}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33186), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 879
write(32, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169671, 251265264}) = 0
gettimeofday({1446109489, 476077}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33218), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 880
write(27, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169672, 320483648}) = 0
gettimeofday({1446109490, 545274}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33232), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 881
write(22, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169676, 186686282}) = 0
gettimeofday({1446109494, 411486}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33303), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 882
write(17, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169684, 699748557}) = 0
gettimeofday({1446109502, 924549}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33320), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 883
write(32, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169687, 906830251}) = 0
gettimeofday({1446109506, 131601}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33348), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 884
write(27, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169701, 112588731}) = 0
gettimeofday({1446109519, 337387}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33386), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 885
write(22, "", 1)                      = 1
epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169707, 686312787}) = 0
gettimeofday({1446109525, 911113}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33420), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 886
write(17, "", 1)                      = 1

cada parte de

epoll_wait(6, {{EPOLLIN, {u32=9, u64=9}}}, 32, -1) = 1
clock_gettime(CLOCK_MONOTONIC, {169707, 686312787}) = 0
gettimeofday({1446109525, 911113}, NULL) = 0
accept4(9, {sa_family=AF_INET, sin_port=htons(33420), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 886
write(17, "", 1)        

é adicionado a cada 3-5 segundos. Nada mais por alguns minutos.

    
por Alexey 28.10.2015 / 20:14

2 respostas

2

Qualquer processo que cria este arquivo é o seu culpado:

gearmand 811 gearman 3w REG 202,1 71016771760 143618 /var/log/gearman-job-server/gearman.log.1 (deleted)

Como é chamado de gearman.log.1 , suspeito que o que estiver fazendo a rolagem de log não esteja sendo feito corretamente.

Quando você vê uma diferença bruta entre df e du , como está vendo, geralmente é um arquivo excluído que um processo ainda está aberto. lsof | grep deleted funciona bem no Linux para encontrá-los.

A simples pesquisa por deleted na sua saída lsof exibida mostra vários outros arquivos de log *.1 que parecem ter o mesmo problema de substituição indevido.

    
por 29.10.2015 / 00:24
1

Apenas outra informação sobre o CentOS. Neste caso, ao usar "systemctl" para o processo de inicialização. Você tem que modificar o arquivo do sistema == > /usr/lib/systemd/system/processName.service .Had esta linha no arquivo:

LimitNOFILE=50000

E recarregue seu sistema:

systemctl daemon-reload
    
por 10.07.2017 / 12:10