You are viewing a plain text version of this content. The canonical link for it is here.
Posted to modperl@perl.apache.org by Ben Mehling <bm...@gmail.com> on 2004/12/01 01:55:47 UTC
[mp2] Win32 apache2 "Restarting" underload
Thanks in advance for looking at this post.
We are running into some trouble porting an existing PERL app running
under an older cgi accelerator (Blue Titan's Velocigen) on IIS to run
under Apache2/mod_perl(1.99) on Win32. We are testing on a Dell dual
P4 xeon(ht), 1GB ram, running win2k3. The DB server is on a separate
host, connecting via DBI/DBD::ODBC.
Our application consists of a handful of perl scripts (.cat files,
essentially .pl's) that call our own libraries (standard .pm files).
The webapp runs fine under our install (Pre-compiled binary:
Perl-5.8-win32-bin-0.8.exe through perl.apache.org) until we place a
load on the server (using jMeter).
Under load we are seeing multiple Apache restarts in the error logs
(see below). The error produced ("Parent: child process exited with
status 3221226324 -- Restarting.") when Apache dies led us to several
mail list threads discussing 'non thread safe' modules (loaded into
Apache) killing it in a similar way (with different status codes)...
We searched through our various modules in use (Apache, Perl 5.8,
mod_perl, Apache::DBI, DBI, DBD::ODBC, DBD::MySQL, Date::Calc,
Net::SMTP) to find if any weren't thread safe. Everything looked
clean. We couldn't find any reason to believe any of the modules
weren't thread safe.
Finally, we wrote a simple script that runs under mod_perl and
accesses the MS SQL server via DBI/DBD::ODBC performing a simple query
(returns 2 columns of 25 rows of data). We loaded up the server using
jMeter to hit this simple script and Apache still dies under load.
Somewhat different results occur if Apache::DBI is enabled or not,
however the difference only appears to be the time it takes to kill
the server.
Overall we can't find any consistency about how long it takes to die
or why it's dying. We may be including a known-bad module or we've
missed something obvious. I hope someone on the list can point us in
the right direction as we are facing a deadline in the next few weeks.
Thank you for your time.
- Ben
===
(I hope including links to public URLs is acceptable, this email is
already quite long.) Here's the relevant conf/version/startup files:
Apache/PERL version info (3KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/beast_config.txt
httpd.conf (36KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/httpd.conf.txt
perl.conf (1KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/perl.conf.txt
startup.pl (1KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/startup.pl.txt
test.cat (test script) (1KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/test.cat.txt
Here are the relevant snippets of testing data and error logs:
/tools/test.cat (jMeter: 50 threads, 1sec ramp-up, infinite loop):
- with apache::dbi ENABLED in startup.pl
- built in ms sql connection pooling disabled
start: 11:28
end: 11:32
Restart after ~10 seconds:
[Mon Nov 22 17:02:51 2004] [notice] Child 5560: Starting 250 worker threads.
[Tue Nov 23 11:28:18 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:28:18 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:28:18 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:28:22 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:28:23 2004] [notice] Parent: Created child process 4152
[Tue Nov 23 11:28:24 2004] [notice] Child 4152: Child process is running
[Tue Nov 23 11:28:25 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4152
[Tue Nov 23 11:28:25 2004] [notice] Child 4152: Acquired the start mutex.
[Tue Nov 23 11:28:25 2004] [notice] Child 4152: Starting 250 worker threads.
Restart after 1 minute:
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:36 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:29:37 2004] [notice] Parent: Created child process 1160
[Tue Nov 23 11:29:39 2004] [notice] Child 1160: Child process is running
[Tue Nov 23 11:29:39 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 1160
[Tue Nov 23 11:29:39 2004] [notice] Child 1160: Acquired the start mutex.
[Tue Nov 23 11:29:39 2004] [notice] Child 1160: Starting 250 worker threads.
Restarts after 3 minutes:
[Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:30:48 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:30:49 2004] [notice] Parent: Created child process 4464
[Tue Nov 23 11:30:51 2004] [notice] Child 4464: Child process is running
[Tue Nov 23 11:30:51 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4464
[Tue Nov 23 11:30:51 2004] [notice] Child 4464: Acquired the start mutex.
[Tue Nov 23 11:30:51 2004] [notice] Child 4464: Starting 250 worker threads.
[Tue Nov 23 11:30:54 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:30:55 2004] [notice] Parent: Created child process 5168
[Tue Nov 23 11:30:56 2004] [notice] Child 5168: Child process is running
[Tue Nov 23 11:30:56 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 5168
[Tue Nov 23 11:30:56 2004] [notice] Child 5168: Acquired the start mutex.
[Tue Nov 23 11:30:56 2004] [notice] Child 5168: Starting 250 worker threads.
[Tue Nov 23 11:31:00 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:31:01 2004] [notice] Parent: Created child process 2032
[Tue Nov 23 11:31:02 2004] [notice] Child 2032: Child process is running
[Tue Nov 23 11:31:02 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 2032
[Tue Nov 23 11:31:02 2004] [notice] Child 2032: Acquired the start mutex.
[Tue Nov 23 11:31:02 2004] [notice] Child 2032: Starting 250 worker threads.
/tools/test.cat (jMeter: 50 threads, 1sec ramp-up, infinite loop)
- with apache::dbi DISABLED in startup.pl
- built in ms sql connection pooling disabled
start: 11:35
end: 11:48
Everything went well for over 10 minutes (111688 requests, rate of
138.6/sec). Control-reloading the page was pretty snappy too. Then
apache restarts a bunch of times and jmeter gets confused, stops
testing:
error log:
[Tue Nov 23 11:34:37 2004] [notice] Child 1868: Starting 250 worker threads.
[Tue Nov 23 11:45:41 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:41 2004] [notice] Parent: Created child process 4484
[Tue Nov 23 11:45:42 2004] [notice] Child 4484: Child process is running
[Tue Nov 23 11:45:42 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4484
[Tue Nov 23 11:45:42 2004] [notice] Child 4484: Acquired the start mutex.
[Tue Nov 23 11:45:42 2004] [notice] Child 4484: Starting 250 worker threads.
[Tue Nov 23 11:45:45 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:46 2004] [notice] Parent: Created child process 2336
[Tue Nov 23 11:45:46 2004] [notice] Child 2336: Child process is running
[Tue Nov 23 11:45:46 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 2336
[Tue Nov 23 11:45:46 2004] [notice] Child 2336: Acquired the start mutex.
[Tue Nov 23 11:45:46 2004] [notice] Child 2336: Starting 250 worker threads.
[Tue Nov 23 11:45:50 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:50 2004] [notice] Parent: Created child process 5364
[Tue Nov 23 11:45:51 2004] [notice] Child 5364: Child process is running
[Tue Nov 23 11:45:51 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 5364
[Tue Nov 23 11:45:51 2004] [notice] Child 5364: Acquired the start mutex.
[Tue Nov 23 11:45:51 2004] [notice] Child 5364: Starting 250 worker threads.
[Tue Nov 23 11:45:55 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:55 2004] [notice] Parent: Created child process 4004
[Tue Nov 23 11:45:56 2004] [notice] Child 4004: Child process is running
[Tue Nov 23 11:45:56 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4004
[Tue Nov 23 11:45:56 2004] [notice] Child 4004: Acquired the start mutex.
[Tue Nov 23 11:45:56 2004] [notice] Child 4004: Starting 250 worker threads.
[Tue Nov 23 11:47:04 2004] [error] [client 128.200.186.240] request
failed: error reading the headers
[Tue Nov 23 11:48:16 2004] [error] [client 128.200.186.240] request
failed: error reading the headers
--
Report problems: http://perl.apache.org/bugs/
Mail list info: http://perl.apache.org/maillist/modperl.html
List etiquette: http://perl.apache.org/maillist/email-etiquette.html
Re: [mp2] Win32 apache2 "Restarting" under load
Posted by Stas Bekman <st...@stason.org>.
Stas Bekman wrote:
> I'll give you a simple technique how to know for sure whether a given
> Perl/XS module is *not* thread-safe. grep its unpacked source for the
> CLONE function. If it doesn't have one, it's not thread-safe. 100%!
that's not 100% correct. It's only correct if the XS returns something
that points to a C data. If it's something that is totaly in Perl domain
(e.g. a string variable), then it's perfectly fine not to have the CLONE
function and still having the module thread-safe. but if it [XS
function/method] returns an object or a handle that internally points to a
C data, then it's certainly thread-unsafe w/o a properly [1] written CLONE
function.
[1] http://apache.org/~stas/Example-CLONE-0.02.tar.gz
--
__________________________________________________________________
Stas Bekman JAm_pH ------> Just Another mod_perl Hacker
http://stason.org/ mod_perl Guide ---> http://perl.apache.org
mailto:stas@stason.org http://use.perl.org http://apacheweek.com
http://modperlbook.org http://apache.org http://ticketmaster.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Win32 apache2 "Restarting" under load
Posted by Stas Bekman <st...@stason.org>.
Ben Mehling wrote:
> On Thu, 02 Dec 2004 16:57:56 -0500, Stas Bekman <st...@stason.org> wrote:
>
>>It's always fun with win32, which never gives proper error messages.
>
>
> "Fun" is one way to describe Win32. :-)
I think windows CD should come bundled with 10 years supply of free milk.
>>I'd start with figuring out what 3221226324 means. Ask on the apache users
>>list? This is a generic Apache message, so it's not on our ground.
>
>
>>It gets the message a few lines above, by calling
>> if (!GetExitCodeProcess(event_handles[CHILD_HANDLE], &exitcode)) {
>>
>>Once you figure out what that number means you will hopefully know the
>>cause of the process exit.
>
>
> An Apache developer told me "the GetExitCodeProcess error just gets
> the return val from mod_perl". I'm not exactly sure how we can be
> sure mod_perl is the module that's freaking out?
Neither do I.
Unfortunately if you ask a question on the Apache list and ever mention
mod_perl, it'll be either ignored or the blame put on mod_perl. That's a
sad truth.
This is of course not to say that mod_perl never was a problem.
> Our setup is pretty
> stripped down at this point... mod_perl is the only non-core module
> loaded up and I've removed a lot of unused core modules for testing.
>
> It also appears that if I throttle back jMeter, Apache doesn't restart
> itself. At least as of yet. Today I was able to place some decent
> load on the server and apache hasn't restarted itself at all.
Any chance you could try the same exercise on a unix machine with worker
mpm, and hopefully the diagnostics will be somewhat more helpful?
(Assuming that the same issue will be encountered).
> Perhaps we were simply overwhelming Apache on this hardware/platform...
Everything and anything is possible. Without being able to reproduce the
problem or at least know the cause we can't do much.
>>>Everything looked clean. We couldn't find any reason to believe
>>>any of the modules weren't thread safe.
>
>
>>Looks clean? You mean you read through the XS and C code? Can you please
>>share how did you come up with that conclusion? (I'd love to learn how to
>>do that)
>
>
> Heh. Fair enough. I should have been more clear: I spent the better
> part of a day looking at the documentation, change logs, and release
> notes for the modules mentioned above. I also searched for discussion
> of these libs on the various mail list archives for any talk of thread
> safety. I was able to determine that either a) the module developer
> was claiming thread-safety OR b) no one was complaining that they
> weren't thread-safe. Probably not conclusive...
>
> Nope, I didn't look through ALL related XS or C code. Sorry. :-)
Another sad truth is that most modules are not run in the threaded
environment, that's the main reason why you can find bug reports.
I'll give you a simple technique how to know for sure whether a given
Perl/XS module is *not* thread-safe. grep its unpacked source for the
CLONE function. If it doesn't have one, it's not thread-safe. 100%!
That reminds me that I need to write an article explaining how to use
CLONE. For now see the docs in:
http://apache.org/~stas/Example-CLONE-0.02.tar.gz
>>I'd also suggest to get rid of these errors:
>>
>>>[Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at (null) line 589.\n
> These "Can't coerce" errors don't always appear when Apache restarts
> itself, so I don't know which is a symptom of the other or if they are
> just two unrelated issues. Carp returns the following chunk:
>
> Can't coerce array into hash at (null) line 589.
> DBI::__ANON__() called at C:/services/Perl/site/lib/DBI.pm line 662
> DBI::connect('DBI', 'dbi:ODBC:cat_prod', 'cat', 'LEE181',
So that comes from DBI, check what it does at line 662 and 589 in DBI.pm.
--
__________________________________________________________________
Stas Bekman JAm_pH ------> Just Another mod_perl Hacker
http://stason.org/ mod_perl Guide ---> http://perl.apache.org
mailto:stas@stason.org http://use.perl.org http://apacheweek.com
http://modperlbook.org http://apache.org http://ticketmaster.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Win32 apache2 "Restarting" under load
Posted by Ben Mehling <bm...@gmail.com>.
On Thu, 02 Dec 2004 16:57:56 -0500, Stas Bekman <st...@stason.org> wrote:
> It's always fun with win32, which never gives proper error messages.
"Fun" is one way to describe Win32. :-)
> I'd start with figuring out what 3221226324 means. Ask on the apache users
> list? This is a generic Apache message, so it's not on our ground.
> It gets the message a few lines above, by calling
> if (!GetExitCodeProcess(event_handles[CHILD_HANDLE], &exitcode)) {
>
> Once you figure out what that number means you will hopefully know the
> cause of the process exit.
An Apache developer told me "the GetExitCodeProcess error just gets
the return val from mod_perl". I'm not exactly sure how we can be
sure mod_perl is the module that's freaking out? Our setup is pretty
stripped down at this point... mod_perl is the only non-core module
loaded up and I've removed a lot of unused core modules for testing.
It also appears that if I throttle back jMeter, Apache doesn't restart
itself. At least as of yet. Today I was able to place some decent
load on the server and apache hasn't restarted itself at all.
Perhaps we were simply overwhelming Apache on this hardware/platform...
> > Everything looked clean. We couldn't find any reason to believe
> > any of the modules weren't thread safe.
> Looks clean? You mean you read through the XS and C code? Can you please
> share how did you come up with that conclusion? (I'd love to learn how to
> do that)
Heh. Fair enough. I should have been more clear: I spent the better
part of a day looking at the documentation, change logs, and release
notes for the modules mentioned above. I also searched for discussion
of these libs on the various mail list archives for any talk of thread
safety. I was able to determine that either a) the module developer
was claiming thread-safety OR b) no one was complaining that they
weren't thread-safe. Probably not conclusive...
Nope, I didn't look through ALL related XS or C code. Sorry. :-)
> I'd also suggest to get rid of these errors:
> > [Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at (null) line 589.\n
> It's quite possible that those are related. Add:
>
> use Carp;
<snip>
These "Can't coerce" errors don't always appear when Apache restarts
itself, so I don't know which is a symptom of the other or if they are
just two unrelated issues. Carp returns the following chunk:
Can't coerce array into hash at (null) line 589.
DBI::__ANON__() called at C:/services/Perl/site/lib/DBI.pm line 662
DBI::connect('DBI', 'dbi:ODBC:cat_prod', 'cat', 'LEE181',
'HASH(0x14e3ff4)') called at
C:/inetpub/webroots/catalyst/cgi/tools/test.cat line 11
ModPerl::ROOT::ModPerl::Registry::C_3a_inetpub_webroots_catalyst_cgi_tools_test_2ecat::handler('Apache::RequestRec=SCALAR(0x9ba418)')
called at C:/services/Perl/site/lib/Apache2/ModPerl/RegistryCooker.pm
line 202
eval {...} called at
C:/services/Perl/site/lib/Apache2/ModPerl/RegistryCooker.pm line 202
ModPerl::RegistryCooker::run('ModPerl::Registry=HASH(0x14e40cc)')
called at C:/services/Perl/site/lib/Apache2/ModPerl/RegistryCooker.pm
line 168
ModPerl::RegistryCooker::default_handler('ModPerl::Registry=HASH(0x14e40cc)')
called at C:/services/Perl/site/lib/Apache2/ModPerl/Registry.pm line
30
ModPerl::Registry::handler('ModPerl::Registry',
'Apache::RequestRec=SCALAR(0x9ba418)') called at -e line 0
eval {...} called at -e line 0
I couldn't find much info on the DBI lists. One suggestion was to
turn tracing on, which I did, but because the error happens so
infrequently and the trace outputs so much data, I haven't been able
to find anything useful.
Regardless of load, this "Can't coerce array in hash" error continues
to come up -- intermittently.
Thanks for your help, Ben
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: [mp2] Win32 apache2 "Restarting" under load
Posted by Stas Bekman <st...@stason.org>.
Ben Mehling wrote:
[Saw your this exact message on the users list, and hoped that someone who
actually uses win32 will be able to give some advise, I guess that's not
the case]
> We are running into some trouble porting an existing PERL app running
> under an older cgi accelerator (Blue Titan's Velocigen) on IIS to run
> under Apache2/mod_perl(1.99) on Win32. We are testing on a Dell dual
> P4 xeon(ht), 1GB ram, running win2k3. The DB server is on a separate
> host, connecting via DBI/DBD::ODBC.
>
> Our application consists of a handful of perl scripts (.cat files,
> essentially .pl's) that call our own libraries (standard .pm files).
> The webapp runs fine under our install (Pre-compiled binary:
> Perl-5.8-win32-bin-0.8.exe through perl.apache.org) until we place a
> load on the server (using jMeter).
>
> Under load we are seeing multiple Apache restarts in the error logs
> (see below). The error produced ("Parent: child process exited with
> status 3221226324 -- Restarting.")
It's always fun with win32, which never gives proper error messages.
I'd start with figuring out what 3221226324 means. Ask on the apache users
list? This is a generic Apache message, so it's not on our ground.
I can point you to server/mpm/winnt/mpm_winnt.c:
else {
int i;
restart_pending = 1;
ap_log_error(APLOG_MARK, APLOG_NOTICE, APR_SUCCESS,
ap_server_conf,
"Parent: child process exited with status %u --
Restarting.", exitcode);
It gets the message a few lines above, by calling
if (!GetExitCodeProcess(event_handles[CHILD_HANDLE], &exitcode)) {
Once you figure out what that number means you will hopefully know the
cause of the process exit.
Alternatively (or may be that process will give nothing useful), try to
shrink your script to the very possible minimum and add debug prints and
in that way you will see what was the last debug statement that was
successful before dieing.
> when Apache dies led us to several
> mail list threads discussing 'non thread safe' modules (loaded into
> Apache) killing it in a similar way (with different status codes)...
>
> We searched through our various modules in use (Apache, Perl 5.8,
> mod_perl, Apache::DBI, DBI, DBD::ODBC, DBD::MySQL, Date::Calc,
> Net::SMTP) to find if any weren't thread safe. Everything looked
> clean. We couldn't find any reason to believe any of the modules
> weren't thread safe.
Looks clean? You mean you read through the XS and C code? Can you please
share how did you come up with that conclusion? (I'd love to learn how to
do that)
I'd also suggest to get rid of these errors:
> [Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at
> (null) line 589.\n
> [Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at
> (null) line 589.\n
It's quite possible that those are related. Add:
use Carp;
$SIG{__DIE__} = \&Carp::confess;
at startup.pl, so you can see where it comes from (must be some eval).
--
__________________________________________________________________
Stas Bekman JAm_pH ------> Just Another mod_perl Hacker
http://stason.org/ mod_perl Guide ---> http://perl.apache.org
mailto:stas@stason.org http://use.perl.org http://apacheweek.com
http://modperlbook.org http://apache.org http://ticketmaster.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
[mp2] Win32 apache2 "Restarting" under load
Posted by Ben Mehling <bm...@gmail.com>.
Thanks in advance for looking at this post.
We are running into some trouble porting an existing PERL app running
under an older cgi accelerator (Blue Titan's Velocigen) on IIS to run
under Apache2/mod_perl(1.99) on Win32. We are testing on a Dell dual
P4 xeon(ht), 1GB ram, running win2k3. The DB server is on a separate
host, connecting via DBI/DBD::ODBC.
Our application consists of a handful of perl scripts (.cat files,
essentially .pl's) that call our own libraries (standard .pm files).
The webapp runs fine under our install (Pre-compiled binary:
Perl-5.8-win32-bin-0.8.exe through perl.apache.org) until we place a
load on the server (using jMeter).
Under load we are seeing multiple Apache restarts in the error logs
(see below). The error produced ("Parent: child process exited with
status 3221226324 -- Restarting.") when Apache dies led us to several
mail list threads discussing 'non thread safe' modules (loaded into
Apache) killing it in a similar way (with different status codes)...
We searched through our various modules in use (Apache, Perl 5.8,
mod_perl, Apache::DBI, DBI, DBD::ODBC, DBD::MySQL, Date::Calc,
Net::SMTP) to find if any weren't thread safe. Everything looked
clean. We couldn't find any reason to believe any of the modules
weren't thread safe.
Finally, we wrote a simple script that runs under mod_perl and
accesses the MS SQL server via DBI/DBD::ODBC performing a simple query
(returns 2 columns of 25 rows of data). We loaded up the server using
jMeter to hit this simple script and Apache still dies under load.
Somewhat different results occur if Apache::DBI is enabled or not,
however the difference only appears to be the time it takes to kill
the server.
Overall we can't find any consistency about how long it takes to die
or why it's dying. We may be including a known-bad module or we've
missed something obvious. I hope someone on the list can point us in
the right direction as we are facing a deadline in the next few weeks.
Thank you for your time.
- Ben
===
(I hope including links to public URLs is acceptable, this email is
already quite long.) Here's the relevant conf/version/startup files:
Apache/PERL version info (3KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/beast_config.txt
httpd.conf (36KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/httpd.conf.txt
perl.conf (1KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/perl.conf.txt
startup.pl (1KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/startup.pl.txt
test.cat (test script) (1KB):
http://projects.gsm.uci.edu/files/gsm/serverupgrade4/test.cat.txt
Here are the relevant snippets of testing data and error logs:
/tools/test.cat (jMeter: 50 threads, 1sec ramp-up, infinite loop):
- with apache::dbi ENABLED in startup.pl
- built in ms sql connection pooling disabled
start: 11:28
end: 11:32
Restart after ~10 seconds:
[Mon Nov 22 17:02:51 2004] [notice] Child 5560: Starting 250 worker threads.
[Tue Nov 23 11:28:18 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:28:18 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:28:18 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:28:22 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:28:23 2004] [notice] Parent: Created child process 4152
[Tue Nov 23 11:28:24 2004] [notice] Child 4152: Child process is running
[Tue Nov 23 11:28:25 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4152
[Tue Nov 23 11:28:25 2004] [notice] Child 4152: Acquired the start mutex.
[Tue Nov 23 11:28:25 2004] [notice] Child 4152: Starting 250 worker threads.
Restart after 1 minute:
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:35 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:29:36 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:29:37 2004] [notice] Parent: Created child process 1160
[Tue Nov 23 11:29:39 2004] [notice] Child 1160: Child process is running
[Tue Nov 23 11:29:39 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 1160
[Tue Nov 23 11:29:39 2004] [notice] Child 1160: Acquired the start mutex.
[Tue Nov 23 11:29:39 2004] [notice] Child 1160: Starting 250 worker threads.
Restarts after 3 minutes:
[Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:30:47 2004] [error] Can't coerce array into hash at
(null) line 589.\n
[Tue Nov 23 11:30:48 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:30:49 2004] [notice] Parent: Created child process 4464
[Tue Nov 23 11:30:51 2004] [notice] Child 4464: Child process is running
[Tue Nov 23 11:30:51 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4464
[Tue Nov 23 11:30:51 2004] [notice] Child 4464: Acquired the start mutex.
[Tue Nov 23 11:30:51 2004] [notice] Child 4464: Starting 250 worker threads.
[Tue Nov 23 11:30:54 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:30:55 2004] [notice] Parent: Created child process 5168
[Tue Nov 23 11:30:56 2004] [notice] Child 5168: Child process is running
[Tue Nov 23 11:30:56 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 5168
[Tue Nov 23 11:30:56 2004] [notice] Child 5168: Acquired the start mutex.
[Tue Nov 23 11:30:56 2004] [notice] Child 5168: Starting 250 worker threads.
[Tue Nov 23 11:31:00 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:31:01 2004] [notice] Parent: Created child process 2032
[Tue Nov 23 11:31:02 2004] [notice] Child 2032: Child process is running
[Tue Nov 23 11:31:02 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 2032
[Tue Nov 23 11:31:02 2004] [notice] Child 2032: Acquired the start mutex.
[Tue Nov 23 11:31:02 2004] [notice] Child 2032: Starting 250 worker threads.
/tools/test.cat (jMeter: 50 threads, 1sec ramp-up, infinite loop)
- with apache::dbi DISABLED in startup.pl
- built in ms sql connection pooling disabled
start: 11:35
end: 11:48
Everything went well for over 10 minutes (111688 requests, rate of
138.6/sec). Control-reloading the page was pretty snappy too. Then
apache restarts a bunch of times and jmeter gets confused, stops
testing:
error log:
[Tue Nov 23 11:34:37 2004] [notice] Child 1868: Starting 250 worker threads.
[Tue Nov 23 11:45:41 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:41 2004] [notice] Parent: Created child process 4484
[Tue Nov 23 11:45:42 2004] [notice] Child 4484: Child process is running
[Tue Nov 23 11:45:42 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4484
[Tue Nov 23 11:45:42 2004] [notice] Child 4484: Acquired the start mutex.
[Tue Nov 23 11:45:42 2004] [notice] Child 4484: Starting 250 worker threads.
[Tue Nov 23 11:45:45 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:46 2004] [notice] Parent: Created child process 2336
[Tue Nov 23 11:45:46 2004] [notice] Child 2336: Child process is running
[Tue Nov 23 11:45:46 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 2336
[Tue Nov 23 11:45:46 2004] [notice] Child 2336: Acquired the start mutex.
[Tue Nov 23 11:45:46 2004] [notice] Child 2336: Starting 250 worker threads.
[Tue Nov 23 11:45:50 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:50 2004] [notice] Parent: Created child process 5364
[Tue Nov 23 11:45:51 2004] [notice] Child 5364: Child process is running
[Tue Nov 23 11:45:51 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 5364
[Tue Nov 23 11:45:51 2004] [notice] Child 5364: Acquired the start mutex.
[Tue Nov 23 11:45:51 2004] [notice] Child 5364: Starting 250 worker threads.
[Tue Nov 23 11:45:55 2004] [notice] Parent: child process exited with
status 3221226324 -- Restarting.
[Tue Nov 23 11:45:55 2004] [notice] Parent: Created child process 4004
[Tue Nov 23 11:45:56 2004] [notice] Child 4004: Child process is running
[Tue Nov 23 11:45:56 2004] [info] Parent: Duplicating socket 220 and
sending it to child process 4004
[Tue Nov 23 11:45:56 2004] [notice] Child 4004: Acquired the start mutex.
[Tue Nov 23 11:45:56 2004] [notice] Child 4004: Starting 250 worker threads.
[Tue Nov 23 11:47:04 2004] [error] [client 128.200.186.240] request
failed: error reading the headers
[Tue Nov 23 11:48:16 2004] [error] [client 128.200.186.240] request
failed: error reading the headers
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org