PHP CLI com IMAP, atraso de inicialização de 5 segundos

2

Tendo instalado o "php-imap-5.3.3-27.el6_5.x86_64" em um servidor RedHat Enterprise 6.5, a versão CLI do PHP sempre leva 5 segundos para ser executada:

php -n -d extension=imap.so -v
PHP 5.3.3 (cli) (built: Dec  5 2013 07:09:40) 
Copyright (c) 1997-2010 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2010 Zend Technologies

real  0m5.023s
user  0m0.006s
sys   0m0.010s

Note que o "-n" desabilita o php.ini usual, e apenas carrega "imap.so" (apenas para fins de depuração).

Você tem ideia do que pode estar causando isso? parece estar fazendo uma pausa para algo, possivelmente um tempo limite?

Não há nada mencionado nos registros de auditoria do SELinux, mas o carregamento interessante da biblioteca parece estar tentando (não?) conectar-se ao servidor DNS por algum motivo?

strace -s -c php -n -d extension=imap.so -v

  execve("/usr/bin/php", [...], [/* 24 vars */]) = 0
  brk(0)                                  = 0x15e2000

[...]

  socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 3
  connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, 16) = 0
  poll([...], 1, 0)                       = 1 ([...])
  sendto(3, ""..., 38, MSG_NOSIGNAL, NULL, 0) = 38
  poll([...], 1, 5000)                    = 1 ([...])
  sendto(3, ""..., 38, MSG_NOSIGNAL, NULL, 0) = 38
  poll([...], 1, 4999)                    = 1 ([...])
  ioctl(3, FIONREAD, [254])               = 0
  recvfrom(3, ""..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, [16]) = 254
  poll([...], 1, 4998

[... 5 second pause ...]

  )                    = 0 (Timeout)
  poll([...], 1, 0)                       = 1 ([...])
  sendto(3, ""..., 38, MSG_NOSIGNAL, NULL, 0) = 38
  poll([...], 1, 5000)                    = 1 ([...])
  ioctl(3, FIONREAD, [254])               = 0
  recvfrom(3, ""..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, [16]) = 254
  poll([...], 1, 4998)                    = 1 ([...])
  sendto(3, ""..., 38, MSG_NOSIGNAL, NULL, 0) = 38
  poll([...], 1, 4998)                    = 1 ([...])
  ioctl(3, FIONREAD, [97])                = 0
  recvfrom(3, ""..., 1794, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}, [16]) = 97
  close(3)                                = 0
  alarm(0)                                = 0

[...]

Tendo verificado com dig, o DNS parece responder bem:

dig +short example.com @192.168.1.1
93.184.216.119

Quanto à saída obrigatória de contagem de strace:

strace -c php -n -d extension=imap.so -v

PHP 5.3.3 (cli) (built: Dec  5 2013 07:09:40)
Copyright (c) 1997-2010 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2010 Zend Technologies

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 27.14    0.000019           0       103           mmap
 25.71    0.000018           0        48           read
 25.71    0.000018           5         4           socket
 21.43    0.000015           0        47           fstat
  0.00    0.000000           0         1           write
  0.00    0.000000           0        49         2 open
  0.00    0.000000           0        51           close
  0.00    0.000000           0         6         2 stat
  0.00    0.000000           0         8           poll
  0.00    0.000000           0         1           lseek
  0.00    0.000000           0        54           mprotect
  0.00    0.000000           0        19           munmap
  0.00    0.000000           0        14           brk
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         6           rt_sigprocmask
  0.00    0.000000           0        12           ioctl
  0.00    0.000000           0         4         3 access
  0.00    0.000000           0         3           alarm
  0.00    0.000000           0         3         2 connect
  0.00    0.000000           0         5           sendto
  0.00    0.000000           0         3           recvfrom
  0.00    0.000000           0         3           recvmsg
  0.00    0.000000           0         1           bind
  0.00    0.000000           0         1           getsockname
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         4           fcntl
  0.00    0.000000           0         1           getcwd
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         1           statfs
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0        11         1 futex
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000070                   473        10 total

E ltrace (com um pouco de memcpy / free / memset time):

ltrace -c php -n -d extension=imap.so -v

PHP 5.3.3 (cli) (built: Dec  5 2013 07:09:40)
Copyright (c) 1997-2010 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2010 Zend Technologies

% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 41.92    7.377898         790      9331 memcpy
 32.32    5.689380         581      9788 free
 11.48    2.021224       14972       135 memset
  7.79    1.371877         147      9297 malloc
  2.86    0.503343         157      3191 strlen
  1.62    0.285582         147      1940 __ctype_tolower_loc
  0.84    0.147136         145      1010 strrchr
  0.37    0.065134         148       440 calloc
  0.21    0.036233         151       239 realloc
  0.14    0.024520       12260         2 getprotobyname
  0.12    0.020486       20486         1 dlopen
  0.07    0.012101         124        97 strcasecmp
  0.07    0.011930         142        84 strtol
  0.06    0.010258         170        60 strchr
  0.02    0.004310         172        25 _setjmp
  0.02    0.003569         148        24 __ctype_b_loc
  0.02    0.002862        2862         1 ERR_load_crypto_strings
  0.01    0.001339         148         9
  0.01    0.001298        1298         1 using_history
  0.01    0.001027         171         6 strncasecmp
  0.01    0.000898         898         1 dlclose
  0.01    0.000893         127         7 getenv
  0.00    0.000682         170         4 fflush
  0.00    0.000371         371         1 tzset
  0.00    0.000358         179         2 xmlParserInputBufferCreateFilenameDefault
  0.00    0.000354         354         1 ERR_load_ERR_strings
  0.00    0.000351         351         1 setlocale
  0.00    0.000346         173         2 xmlSetGenericErrorFunc
  0.00    0.000341         170         2 xmlOutputBufferCreateFilenameDefault
  0.00    0.000326         163         2 signal
  0.00    0.000326         163         2 __strtok_r
  0.00    0.000312         312         1 SSL_library_init
  0.00    0.000303         303         1 OpenSSL_add_all_ciphers
  0.00    0.000282         282         1 EVP_cleanup
  0.00    0.000253         253         1 xmlInitParser
  0.00    0.000245         245         1 OPENSSL_add_all_algorithms_noconf
  0.00    0.000224         224         1 write
  0.00    0.000223         223         1 sigprocmask
  0.00    0.000191         191         1 OpenSSL_add_all_digests
  0.00    0.000187         187         1 xmlCleanupParser
  0.00    0.000178         178         1 xmlSetStructuredErrorFunc
  0.00    0.000176         176         1 xmlRelaxNGCleanupTypes
  0.00    0.000175         175         1 ERR_load_EVP_strings
  0.00    0.000175         175         1 X509_get_default_cert_area
  0.00    0.000172         172         1 sigemptyset
  0.00    0.000171         171         1 xmlResetLastError
  0.00    0.000170         170         1 strncmp
  0.00    0.000169         169         1 time
  0.00    0.000169         169         1 sigaddset
  0.00    0.000167         167         1 SSL_get_ex_new_index
  0.00    0.000154         154         1 __gmp_set_memory_functions
  0.00    0.000153         153         1 pcre_version
  0.00    0.000151         151         1 gnu_get_libc_version
  0.00    0.000145         145         1 __xmlParserVersion
  0.00    0.000092          92         1 getcwd
  0.00    0.000079          79         1 dlsym
  0.00    0.000072          72         1 __strdup
------ ----------- ----------- --------- --------------------
100.00   17.601541                 35732 total

Relacionado, mas não resolvido por:

http://superuser.com/questions/336177/running-php-as-cli-takes-a-long-time
http://trac.macports.org/ticket/35222
https://bugs.php.net/bug.php?id=41968
https://github.com/liip/php-osx/issues/102
    
por Craig Francis 02.04.2014 / 13:45

1 resposta

2

Não é uma resposta completa ... mas está assistindo a saída de:

tcpdump -vvv port 53

Mostrado que o servidor estava tentando resolver seu nome de host ... agora, enquanto dig pode resolver isso, suponho que algo (SELinux?) esteja bloqueando php ?

Então, adicionando uma entrada ao arquivo /etc/hosts :

127.0.0.1   example.net

Parece ter feito o truque:

time php -n -d extension=imap.so -v
PHP 5.3.3 (cli) (built: Dec  5 2013 07:09:40) 
Copyright (c) 1997-2010 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2010 Zend Technologies

real  0m0.011s
user  0m0.007s
sys   0m0.003s

Eu provavelmente vou deixá-lo lá ... mas ele ainda levanta a questão, por que foi impossível fazer uma pesquisa de DNS, e por que a biblioteca (mesmo sem ser usada) até mesmo tentou fazer uma pesquisa de DNS?

    
por 02.04.2014 / 13:57