Hi!

I have additional information:

/var/log/httpd/error_log, at "crash time": [Fri Sep 30 19:09:03.897325
2016] [mpm_event:trace4] [pid 30339:tid 139796798162688] event.c(930):
socket reached timeout in lingering-close state

What do you think?


2016-09-30 14:47 GMT+02:00 Fabio F.Gervasi <fabio.gervas...@gmail.com>:

> Hi!
>
> Thank you for your reply. I tried the following tests.
>
> *1) Using a little text file:*
> *# ab -k -c 100 -n 2000 localhost/test.txt*
> This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
> Licensed to The Apache Software Foundation, http://www.apache.org/
>
> Benchmarking localhost (be patient)
> Completed 200 requests
> Completed 400 requests
> Completed 600 requests
> Completed 800 requests
> Completed 1000 requests
> Completed 1200 requests
> Completed 1400 requests
> Completed 1600 requests
> Completed 1800 requests
> Completed 2000 requests
> Finished 2000 requests
>
>
> Server Software:        Apache/2.4.23
> Server Hostname:        localhost
> Server Port:            80
>
> Document Path:          /test.txt
> Document Length:        52 bytes
>
> Concurrency Level:      100
> Time taken for tests:   2.521 seconds
> Complete requests:      2000
> *Failed requests:        16*
>    (Connect: 0, Receive: 0, Length: 16, Exceptions: 0)
> Keep-Alive requests:    1984
> Total transferred:      950336 bytes
> HTML transferred:       103168 bytes
> Requests per second:    793.45 [#/sec] (mean)
> Time per request:       126.032 [ms] (mean)
> Time per request:       1.260 [ms] (mean, across all concurrent requests)
> Transfer rate:          368.18 [Kbytes/sec] received
>
> Connection Times (ms)
>               min  mean[+/-sd] median   max
> Connect:        0    1   3.8      0      21
> Processing:     1  123 126.5     83     772
> Waiting:        0  123 126.7     83     772
> Total:          1  124 126.6     85     772
>
> Percentage of the requests served within a certain time (ms)
>   50%     85
>   66%    154
>   75%    201
>   80%    229
>   90%    303
>   95%    373
>   98%    452
>   99%    547
>  100%    772 (longest request)
>
> *I obtain 16 failed requests, but if I run more again I obtain a different
> number.*
>
> *2) Using a big gif file:*
> *# ab -k -c 100 -n 2000 localhost/it-vis-animation.gif*
> This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
> Licensed to The Apache Software Foundation, http://www.apache.org/
>
> Benchmarking localhost (be patient)
> Completed 200 requests
> Completed 400 requests
> Completed 600 requests
> Completed 800 requests
> Completed 1000 requests
> Completed 1200 requests
> Completed 1400 requests
> Completed 1600 requests
> Completed 1800 requests
> Completed 2000 requests
> Finished 2000 requests
>
>
> Server Software:        Apache/2.4.23
> Server Hostname:        localhost
> Server Port:            80
>
> Document Path:          /it-vis-animation.gif
> Document Length:        8105309 bytes
>
> Concurrency Level:      100
> Time taken for tests:   26.294 seconds
> Complete requests:      2000
> *Failed requests:        0*
> Keep-Alive requests:    2000
> Total transferred:      16211484000 bytes
> HTML transferred:       16210618000 bytes
> Requests per second:    76.06 [#/sec] (mean)
> Time per request:       1314.691 [ms] (mean)
> Time per request:       13.147 [ms] (mean, across all concurrent requests)
> Transfer rate:          602100.83 [Kbytes/sec] received
>
> Connection Times (ms)
>               min  mean[+/-sd] median   max
> Connect:        0    1   4.0      0      22
> Processing:   404 1309  80.0   1298    1635
> Waiting:        5   22  32.4     10     207
> Total:        420 1310  80.6   1298    1635
>
> Percentage of the requests served within a certain time (ms)
>   50%   1298
>   66%   1315
>   75%   1342
>   80%   1360
>   90%   1397
>   95%   1440
>   98%   1513
>   99%   1530
>  100%   1635 (longest request)
>
> *In this case I obtain always 0 failed!*
>
> *3) Using a little png file:*
> *# ab -k -c 100 -n 2000 localhost/apple-touch-icon.png*
> This is ApacheBench, Version 2.3 <$Revision: 1748469 $>
> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
> Licensed to The Apache Software Foundation, http://www.apache.org/
>
> Benchmarking localhost (be patient)
> Completed 200 requests
> Completed 400 requests
> Completed 600 requests
> Completed 800 requests
> Completed 1000 requests
> Completed 1200 requests
> Completed 1400 requests
> Completed 1600 requests
> Completed 1800 requests
> Completed 2000 requests
> Finished 2000 requests
>
>
> Server Software:        Apache/2.4.23
> Server Hostname:        localhost
> Server Port:            80
>
> Document Path:          /apple-touch-icon.png
> Document Length:        12364 bytes
>
> Concurrency Level:      100
> Time taken for tests:   2.576 seconds
> Complete requests:      2000
> *Failed requests:        22*
>    (Connect: 0, Receive: 0, Length: 22, Exceptions: 0)
> Keep-Alive requests:    1978
> Total transferred:      25304554 bytes
> HTML transferred:       24455992 bytes
> Requests per second:    776.52 [#/sec] (mean)
> Time per request:       128.779 [ms] (mean)
> Time per request:       1.288 [ms] (mean, across all concurrent requests)
> Transfer rate:          9594.53 [Kbytes/sec] received
>
> Connection Times (ms)
>               min  mean[+/-sd] median   max
> Connect:        0    1   3.9      0      20
> Processing:     0  125 112.0    101     563
> Waiting:        0  125 112.1    101     563
> Total:          0  126 112.6    102     563
>
> Percentage of the requests served within a certain time (ms)
>   50%    102
>   66%    159
>   75%    196
>   80%    220
>   90%    282
>   95%    354
>   98%    401
>   99%    457
>  100%    563 (longest request)
>
> *I get 22 failed requests, but if I run more again I obtain a different
> number.*
>
> What do you thing?
>
> Thank you!
>
>
>
> 2016-09-30 13:50 GMT+02:00 Daniel <dferra...@gmail.com>:
>
>> hello,
>>
>> the fact that all those 500 error reponses go with "X-Powered-By:
>> PHP/5.6.26" tell me it is php giving those errors.
>>
>> If you are still unsure, you could use the ab tool from Apache HTTPD, and
>> request a specific static file (text, gif) hundreds of times to see if you
>> get a 500 error from HTTPD.
>>
>> 2016-09-30 8:59 GMT+02:00 Fabio F.Gervasi <fabio.gervas...@gmail.com>:
>>
>>> Hi,
>>>
>>> I'm not 100% sure that the real source of the problem is apache (could
>>> be php or other), but I'd like start from here as the only logs that
>>> provides me with information (with trace4 level) is apache log. No
>>> information appears from other logs.
>>>
>>> I have:
>>> - Linux 4.7.4-100.fc23.x86_64
>>> - Server version: Apache/2.4.23 (Fedora)
>>> - mysql  Ver 15.1 Distrib 10.0.26-MariaDB, for Linux (x86_64) using
>>> readline 5.1
>>> - PHP Version => 5.6.25
>>>
>>> The problem: random internal server error 500. Random because, for
>>> example, if a page produces the error and do "reload" then it works. The
>>> same page may not work as well as work. Sometimes you can use the site for
>>> several minutes with no problems, then suddenly there is the error.
>>>
>>> When error occurs, this is all that I get from the log file (with
>>> loglevel = trace4):
>>>
>>> [...]
>>> [Fri Sep 30 07:41:39.151052 2016] [rewrite:trace3] [pid 17957:tid
>>> 140241771534080] mod_rewrite.c(477): [client 151.25.206.200:38368]
>>> 151.25.206.200 - - [www.centrometeo.com/sid#55c3e
>>> 3673400][rid#7f8c8000e9d0/subreq
>>> <http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
>>> [perdir /home/web/centrometeo.com/] applying pattern '.*' to uri
>>> 'index.php', referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.151092 2016] [rewrite:trace1] [pid 17957:tid
>>> 140241771534080] mod_rewrite.c(477): [client 151.25.206.200:38368]
>>> 151.25.206.200 - - [www.centrometeo.com/sid#55c3e
>>> 3673400][rid#7f8c8000e9d0/subreq
>>> <http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
>>> [perdir /home/web/centrometeo.com/] pass through /home/web/
>>> centrometeo.com/index.php, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913003 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(567): [client 151.25.206.200:38368]
>>> Headers from script 'php.fcgi':, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913097 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]   
>>> *Status:
>>> 500 Internal Server Error*, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913130 2016] [core:trace1] [pid 17957:tid
>>> 140241771534080] util_script.c(649): [client 151.25.206.200:38368] *Status
>>> line from script 'php.fcgi': 500 Internal Server Error*, referer:
>>> http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/
>>> 559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913162 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>> X-Powered-By: PHP/5.6.26, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913191 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>> P3P: CP="NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM", referer:
>>> http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/
>>> 559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913218 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>> Content-Encoding: gzip, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913246 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>> Vary: Accept-Encoding, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913275 2016] [core:trace4] [pid 17957:tid
>>> 140241771534080] util_script.c(568): [client 151.25.206.200:38368]
>>> Content-type: text/html; charset=UTF-8, referer:
>>> http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/
>>> 559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913395 2016] [http:trace3] [pid 17957:tid
>>> 140241771534080] http_filters.c(1006): [client 151.25.206.200:38368] 
>>> *Response
>>> sent with status 500, headers:*, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913432 2016] [http:trace4] [pid 17957:tid
>>> 140241771534080] http_filters.c(835): [client 151.25.206.200:38368]
>>> X-Powered-By: PHP/5.6.26, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913458 2016] [http:trace4] [pid 17957:tid
>>> 140241771534080] http_filters.c(835): [client 151.25.206.200:38368]
>>> P3P: CP=\\"NOI ADM DEV PSAi COM NAV OUR OTRo STP IND DEM\\", referer:
>>> http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/
>>> 559-wrf-mslp-6hprec-ita
>>> [Fri Sep 30 07:41:39.913481 2016] [http:trace4] [pid 17957:tid
>>> 140241771534080] http_filters.c(835): [client 151.25.206.200:38368]
>>> Content-Encoding: gzip, referer: http://www.centrometeo.com/mod
>>> elli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>>> [...]
>>>
>>> Note the use of fcgi. Apache is indeed configured with
>>> event/php-fpm/FastCGI, but the same thing happens with "normal" prefork /
>>> php!
>>> Until a few days ago it did not happen, it started after updating the
>>> system (kernel, apache, php, mariadb).
>>> I do not really know what to do.
>>>
>>> Thank you very much.
>>> Fabio.
>>>
>>
>>
>>
>> --
>> *Daniel Ferradal*
>> IT Specialist
>>
>> email         dferradal at gmail.com
>> linkedin     es.linkedin.com/in/danielferradal
>>
>
>

Reply via email to