Req In Process Versus Req / sec

[Tris]

Hi Guys

For the last day or so the Requests in Processing has been much higher than the Req / Second.

Requests in programming between 500 and 1500 and the Req/Sec is only around 200.

I have increased everything I could think of that would try and remidy this (PHP connections etc etc etc) but nothing seems to be working. This is causing the site to be really slow loading. There is a delay of about... 5 seconds before it starts loading.

Just wondering if any of you have any experience with this or anything like that

[auser]

there was a similar case before when bottleneck is at MySQL.

a tip to check MySQL performance:
#mysqladmin processlist

[Tris]

Already did :-P MySQL is on a dedicated server. I have confirmed at tested that there is no issue with the MySQL

[EDIT] or the connection, which is via private network

[auser]

then please check:

IOWait (can simply check it by top)

memory limit for php process

[Tris]

iowait is fine. Soft Memory limit is 450M and hard is 500M

[auser]

can you post the output of "top" here?

[Tris]

top - 16:20:45 up 32 days,  8:49,  2 users,  load average: 7.69, 7.09, 7.56
Tasks: 467 total,   7 running, 435 sleeping,   0 stopped,  25 zombie
Cpu(s): 31.7%us,  1.0%sy,  0.0%ni, 66.5%id,  0.0%wa,  0.1%hi,  0.7%si,  0.0%st
Mem:  49457604k total, 24374084k used, 25083520k free,  8156932k buffers
Swap:  4192956k total,        0k used,  4192956k free, 13440892k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
25487 theybf    15   0 45928  28m 1872 S 24.2  0.1   0:06.13 lsphp5
25348 theybf    15   0 47536  29m 1872 S 21.9  0.1   0:15.70 lsphp5
25442 theybf    15   0 47516  29m 1872 S 19.9  0.1   0:11.45 lsphp5
25480 theybf    15   0 46080  28m 1872 S 18.6  0.1   0:06.01 lsphp5
25280 theybf    15   0 51732  33m 1876 S 18.2  0.1   0:30.23 lsphp5
25345 theybf    15   0 46284  28m 1872 S 17.9  0.1   0:17.59 lsphp5
25444 theybf    15   0 46068  28m 1872 S 17.9  0.1   0:11.79 lsphp5
25449 theybf    16   0 46032  28m 1880 R 17.6  0.1   0:06.83 lsphp5
25450 theybf    15   0 46296  28m 1872 R 17.2  0.1   0:09.27 lsphp5
25478 theybf    15   0 46508  28m 1872 S 16.9  0.1   0:06.19 lsphp5
25486 theybf    15   0 45772  27m 1880 S 16.9  0.1   0:06.04 lsphp5
25476 theybf    15   0 46104  28m 1872 S 16.6  0.1   0:06.51 lsphp5
25479 theybf    16   0 46024  28m 1872 S 16.6  0.1   0:06.39 lsphp5
25439 theybf    15   0 46372  28m 1872 S 16.2  0.1   0:12.16 lsphp5
25484 theybf    15   0 46344  28m 1872 S 16.2  0.1   0:06.26 lsphp5
25490 theybf    15   0 45812  28m 1872 R 16.2  0.1   0:06.48 lsphp5
25493 theybf    15   0 46468  28m 1880 S 16.2  0.1   0:06.35 lsphp5

This was from around the time it was at its worst

[auser]

when it's worse again, strace the busiest lsphp5 process.
in the above top output, it's the one pid=25487

then
#strace -c -p 25487

(until it quits automatically)

paste the output here, let's see if we can get any clue from it.

[Tris]

[root@server1 ~]# strace -c -p 16283
Process 16283 attached - interrupt to quit
Process 16283 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 81.22    0.073741           1    142837      1006 read
  6.87    0.006242          88        71           connect
  3.10    0.002812         937         3           brk
  2.78    0.002524           0     46388        71 lstat
  1.10    0.000999          10       103           select
  1.03    0.000934           0      2912       840 access
  0.97    0.000884           0      5951        71 open
  0.75    0.000685           1      1148           write
  0.45    0.000409           0      5956           close
  0.44    0.000403           0      6022           getcwd
  0.44    0.000400           0      6960       150 stat
  0.38    0.000348           1       371         4 writev
  0.18    0.000167           0     11618           lseek
  0.11    0.000098           0     11618           fstat
  0.06    0.000058           0       143           chdir
  0.05    0.000046           1        71           socket
  0.03    0.000028           0       213           setsockopt
  0.02    0.000016           0      2087           fcntl
  0.00    0.000000           0       286           rt_sigaction
  0.00    0.000000           0       142           rt_sigprocmask
  0.00    0.000000           0       214           setitimer
  0.00    0.000000           0         4           accept
  0.00    0.000000           0        72           shutdown
  0.00    0.000000           0        71           readlink
  0.00    0.000000           0        27           getppid
------ ----------- ----------- --------- --------- ----------------
100.00    0.090794                245288      2142 total

[auser]

Originally Posted by Tris

[root@server1 ~]# strace -c -p 16283
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 81.22    0.073741           1    142837      1006 read

so most of the time(81.22%) is trying to read something, maybe infinite loop in php script?

can further trace what the lsphp5 process is trying to read:
#strace -e read -p xxx -o info.txt

check info.txt, see if something unusual.