httpd-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Dr James Smith <...@sanger.ac.uk>
Subject Re: [users@httpd] Random Internal Server Error 500 after apache and system update
Date Sun, 02 Oct 2016 08:34:36 GMT
Things you can do are trying to track down if there is any pattern - are 
these first request on a child, "nth" request on  child etc... we add 
additional variables to access logs which include things such as 
PID/request no in PID, memory usage before and after etc. This allows us 
sometimes to see patterns in errors which aren't normally easy to see..
Saying that it may not help you here...

Another thing you can do with ab is check to see if it is OK under lower 
load?

Finally I find "siege" better than "ab" when it comes to testing as it 
is more configurable - you can send it a list of URLs - run test for 
"n-seconds" rather than "n-requests" which is more useful if you don't 
know how long things take to return!

James

On 02/10/2016 09:02, Daniel wrote:
> I would bet on your method of parsing php and the scripts being ran, 
> in any case to be sure:
>
> Try the strace approach:
> strace -o /tmp/outputfile -s 5000 httpd -X or strace -ff -F -s200 -o 
> /tmp/strace.out -p PID
>
> to try to find out what's really going on.
>
> 2016-09-30 20:19 GMT+02:00 Fabio F.Gervasi <fabio.gervasi70@gmail.com 
> <mailto:fabio.gervasi70@gmail.com>>:
>
>     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.gervasi70@gmail.com <mailto:fabio.gervasi70@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 <dferradal@gmail.com
>         <mailto:dferradal@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.gervasi70@gmail.com
>             <mailto:fabio.gervasi70@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
>                 <http://151.25.206.200:38368>] 151.25.206.200 - -
>                 [www.centrometeo.com/sid#55c3e3673400][rid#7f8c8000e9d0/subreq
>                 <http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
>                 [perdir /home/web/centrometeo.com/
>                 <http://centrometeo.com/>] applying pattern '.*' to
>                 uri 'index.php', referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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
>                 <http://151.25.206.200:38368>] 151.25.206.200 - -
>                 [www.centrometeo.com/sid#55c3e3673400][rid#7f8c8000e9d0/subreq
>                 <http://www.centrometeo.com/sid#55c3e3673400][rid%237f8c8000e9d0/subreq>]
>                 [perdir /home/web/centrometeo.com/
>                 <http://centrometeo.com/>] pass through
>                 /home/web/centrometeo.com/index.php
>                 <http://centrometeo.com/index.php>, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://151.25.206.200:38368>]
>                 Headers from script 'php.fcgi':, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://151.25.206.200:38368>]
>                 *Status: 500 Internal Server Error*, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://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
>                 <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 <http://151.25.206.200:38368>]  
>                 X-Powered-By: PHP/5.6.26, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://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
>                 <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 <http://151.25.206.200:38368>]
>                 Content-Encoding: gzip, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://151.25.206.200:38368>]  
>                 Vary: Accept-Encoding, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://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
>                 <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
>                 <http://151.25.206.200:38368>] *Response sent with
>                 status 500, headers:*, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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
>                 <http://151.25.206.200:38368>]   X-Powered-By:
>                 PHP/5.6.26, referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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
>                 <http://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
>                 <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
>                 <http://151.25.206.200:38368>] Content-Encoding: gzip,
>                 referer:
>                 http://www.centrometeo.com/modelli-numerici/modello-wrf-nmm/559-wrf-mslp-6hprec-ita
>                 <http://www.centrometeo.com/modelli-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 <http://gmail.com>
>             linkedin es.linkedin.com/in/danielferradal
>             <http://es.linkedin.com/in/danielferradal>
>
>
>
>
>
>
> -- 
> *Daniel Ferradal*
> IT Specialist
>
> email dferradal at gmail.com <http://gmail.com>
> linkedin es.linkedin.com/in/danielferradal 
> <http://es.linkedin.com/in/danielferradal>




-- 
 The Wellcome Trust Sanger Institute is operated by Genome Research 
 Limited, a charity registered in England with number 1021457 and a 
 company registered in England with number 2742969, whose registered 
 office is 215 Euston Road, London, NW1 2BE. 
Mime
View raw message