You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@perl.apache.org by Stas Bekman <st...@stason.org> on 2003/09/18 11:41:00 UTC
open_logs/post_config run 4 times instead of 2 on win32
[moving this issue into a dedicated thread]
Steve Hay wrote:
[...]
>> I've appended the [$tid] before the original message.
>
>
> Here's what I get:
>
> [Wed Sep 17 10:35:43 2003] - open_logs : [212] process 2420 is born to
> reproduce
> [Wed Sep 17 10:35:43 2003] - post_config: [212] configuration is completed
> [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:44 2003] - open_logs : [212] process 2420 is born to
> reproduce
> [Wed Sep 17 10:35:44 2003] - post_config: [212] configuration is completed
> [Wed Sep 17 10:35:45 2003] - open_logs : [1928] process 3156 is born to
> reproduce
> [Wed Sep 17 10:35:45 2003] - post_config: [1928] configuration is completed
> [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:45 2003] - open_logs : [1928] process 3156 is born to
> reproduce
> [Wed Sep 17 10:35:45 2003] - post_config: [1928] configuration is completed
> [Wed Sep 17 10:35:46 2003] - child_init : [1928] process 3156 is born to
> serve
>
> [Wed Sep 17 10:35:58 2003] - child_exit : [1928] process 3156 now exits
> [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
> [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
>
> That doesn't look a lot more useful to me than the previous output -
> there's just a 1-1 correspondence of PID-TID.
Sure, I was just checking whether there were more than one thread. Looks like
the END problem is ours (modperl), since I can reproduce it with worker.
However open_logs and post_config running 4 times doesn't seem right, and
mod_perl has no control over it. Could you try to set a breakpoint in
modperl_hook_post_config and look at the traces with an aim to figure out why
this happens four times? Remember that apache restarts itself, so 2 times is
the right answer. Thanks Steve.
__________________________________________________________________
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: open_logs/post_config run 4 times instead of 2 on win32
Posted by Stas Bekman <st...@stason.org>.
Stas Bekman wrote:
> Geoffrey Young wrote:
>
>>
>>> However open_logs and post_config running 4 times doesn't seem right,
>>> and mod_perl has no control over it. Could you try to set a
>>> breakpoint in modperl_hook_post_config and look at the traces with an
>>> aim to figure out why this happens four times? Remember that apache
>>> restarts itself, so 2 times is the right answer.
I've just realized that printing out $$/$tid is not very helpful, since tid
doesn't map 1:1 to the perl interpreter, so what we really need is
$$/interpreter id, which can easily be done in the tracing C code, but not
from the perl code. I'm thinking of providing an accessor to print the current
perl interpreter address from the perl code, or is there one already in perl
that I don't know about? Some B:: or Devel:: module?
__________________________________________________________________
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: open_logs/post_config run 4 times instead of 2 on win32
Posted by Stas Bekman <st...@stason.org>.
Geoffrey Young wrote:
>
>> However open_logs and post_config running 4 times doesn't seem right,
>> and mod_perl has no control over it. Could you try to set a breakpoint
>> in modperl_hook_post_config and look at the traces with an aim to
>> figure out why this happens four times? Remember that apache restarts
>> itself, so 2 times is the right answer.
>
>
> I don't know that you can necessarily say that. win32 is it's own mpm,
> so its model might be quite different than what we ordinarily expect on
> unix. as you said, we have little if any control over it.
Well, it sounds wrong, because if you write a handler which opens logs it
should happen only twice by design. I admit I know nothing about winnt mpm,
but it's possible that nobody has used those phases on winnt mpm and therefore
didn't notice the problem. So it's quite possible that there is a bug in the
mpm. It'd be nice if someone who's using this mpm would ask httpd-dev, and
hopefully the list will be so kind to reply.
the multiple END running is obviously a bug on our side of river.
> <handwaving>
> perhaps asking httpd-dev or coming up with a pure C module for those
> hooks would shed some light. the ORA apache book has a module that
> hooks into everything, and might be a simple way to test it
>
> http://examples.oreilly.com/apache3/
>
> </handwaving>
there is also mod_example.c which is written for this reason I think.
__________________________________________________________________
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: open_logs/post_config run 4 times instead of 2 on win32
Posted by Geoffrey Young <ge...@modperlcookbook.org>.
> However open_logs and post_config running 4 times doesn't seem
> right, and mod_perl has no control over it. Could you try to set a
> breakpoint in modperl_hook_post_config and look at the traces with an
> aim to figure out why this happens four times? Remember that apache
> restarts itself, so 2 times is the right answer.
I don't know that you can necessarily say that. win32 is it's own mpm, so
its model might be quite different than what we ordinarily expect on unix.
as you said, we have little if any control over it.
<handwaving>
perhaps asking httpd-dev or coming up with a pure C module for those hooks
would shed some light. the ORA apache book has a module that hooks into
everything, and might be a simple way to test it
http://examples.oreilly.com/apache3/
</handwaving>
:)
--Geoff
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@perl.apache.org
For additional commands, e-mail: dev-help@perl.apache.org
Re: open_logs/post_config run 4 times instead of 2 on win32
Posted by Stas Bekman <st...@stason.org>.
Bill Stoddard wrote:
> Stas Bekman wrote:
>
>> Bill and Bill, do you have any idea why do we get post_config and
>> open_logs phases run 4 times instead of 2 (start+restart) on winnt
>> mpm? It looks like each process that starts does its own config phase.
>
>
> Yep, that's exactly right. Windows does not support fork(), so each
> process will run all the startup phase hooks. Twice.
Aha, so Geoff was right, that we can't make any assumption of behavior in
different mpms.
> You can use code
> like this to prevent the running a hook twice or running it in the
> parent process:
What constitutes a parent process if you can't fork?
>
> /* Run post_config only on the second config pass */
> apr_pool_userdata_get(&data, userdata_key, server_conf->process->pool);
> if (!data) {
> apr_pool_userdata_set((const void *)1, userdata_key,
> apr_pool_cleanup_null,
> server_conf->process->pool);
> return OK;
> }
Yes, I know that trick (even suggested a common API which was never added),
but start+restart are not a problem I think.
The problem could be the running of these phases by each process. So below you
suggest to skip the run of post_config, open_logs in the child processes,
right? I'm not sure whether this is a good, as my guess is that on the
opposite you may want to run inside each child but not the parent, if you want
to setup some data to be visible by the child processes.
> #ifdef WIN32
> /* Do not run post_config in the Windows parent process
> * The envar AP_PARENT_PID is set in the env list (by mpm_winnt)
> * for the child process.
> * **WARNING**:
> * This check is not as robust as I would like because the name of this
> * envar is subject to change. Apache2 needs something like
> * ap_mpm_query(AP_MPMQ_IS_PARENT,&rc);
> */
>
> if (!getenv("AP_PARENT_PID")) {
> /* This is the parent, process */
> }
> #endif
So is this AP_PARENT_PID env var there to stay? In which case we have all we
need to control the bahavior. Thanks Bill
---
Steve, Randy, so we have two parts to deal with:
1) mod_perl's own post_config and open_logs hooks - we need to see whether
they need to be run in the parent, child or both. e.g. the END blocks must not
be run too many or too few times.
2) next, user's custom post_config and open_logs hooks could use the above C
techniques (though coded in Perl) to have a complete control over when what
happens. The sucky part is that a 3rd party module developer writing a
post_config and open_logs hooks won't be aware of these winnt mpm specifics. sigh.
You probably have much more undestanding of the above in the winnt land. So
I'd leave it to you to take the further steps to document this behavior and
suggest any special patches if such are required. Thanks.
__________________________________________________________________
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: open_logs/post_config run 4 times instead of 2 on win32
Posted by Stas Bekman <st...@stason.org>.
Bill and Bill, do you have any idea why do we get post_config and open_logs
phases run 4 times instead of 2 (start+restart) on winnt mpm? It looks like
each process that starts does its own config phase.
The original observation report is here:
http://marc.theaimsgroup.com/?l=apache-modperl-dev&m=106379151724265&w=2
Thanks!
> Steve Hay wrote:
> > Here's what I get:
> >
> > [Wed Sep 17 10:35:43 2003] - open_logs : [212] process 2420 is born to
> > reproduce
> > [Wed Sep 17 10:35:43 2003] - post_config: [212] configuration is
> completed
> > [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:43 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:44 2003] - open_logs : [212] process 2420 is born to
> > reproduce
> > [Wed Sep 17 10:35:44 2003] - post_config: [212] configuration is
> completed
> > [Wed Sep 17 10:35:45 2003] - open_logs : [1928] process 3156 is born to
> > reproduce
> > [Wed Sep 17 10:35:45 2003] - post_config: [1928] configuration is
> completed
> > [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:45 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:45 2003] - open_logs : [1928] process 3156 is born to
> > reproduce
> > [Wed Sep 17 10:35:45 2003] - post_config: [1928] configuration is
> completed
> > [Wed Sep 17 10:35:46 2003] - child_init : [1928] process 3156 is born to
> > serve
> >
> > [Wed Sep 17 10:35:58 2003] - child_exit : [1928] process 3156 now exits
> > [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [1928] process 3156 is
> shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
> > [Wed Sep 17 10:35:58 2003] - END : [212] process 2420 is shutdown
__________________________________________________________________
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