Steve Hay wrote:
Stas Bekman wrote:
Steve Hay wrote:
With the LogLevel set appropriately, I actually get the message coming out *four* times when I start the server:
[Tue Sep 16 09:22:43 2003] [info] mod_perl: using Perl HASH_SEED: 2294822312
[Tue Sep 16 09:22:44 2003] [info] mod_perl: using Perl HASH_SEED: 3042930004
[Tue Sep 16 09:22:44 2003] [notice] Parent: Created child process 2336
[Tue Sep 16 09:22:44 2003] [debug] mpm_winnt.c(505): Parent: Sent the scoreboard to the child
[Tue Sep 16 09:22:45 2003] [info] mod_perl: using Perl HASH_SEED: 3745517160
[Tue Sep 16 09:22:46 2003] [info] mod_perl: using Perl HASH_SEED: 370731127
[Tue Sep 16 09:22:46 2003] [notice] Child 2336: Child process is running
...
Is that as expected? I was only expecting to see it once, or maybe once in the parent and once in the child, but I'm sure I'm just missing something.
Interesting. It should happen twice, but for a different reason: apache restarts itself once it's started. See: http://perl.apache.org/docs/2.0/user/handlers/server.html#Startup_Phases_Demonstration_Module
Do you get the PostConfig handler run four times as well?
I wonder why does it run 4 times instead of 2. Moreover it reports 4 different hash seed values, whereas it should differ only between start and restart (but since I don't know where the other two calls came from i can't tell). I tested with worker mpm and it does only 2. may be its a winnt mpm that does that on purpose, or may be it's a bug in that mpm?
I installed the demo module referred to by your link above and yes, the PostConfigHandler does run four times. Here's startup.log which that module produced (I just started the server, paused, and then stopped it):
I did know you could pause the server ;)
[Tue Sep 16 10:25:16 2003] - open_logs : process 1128 is born to reproduce
[Tue Sep 16 10:25:16 2003] - post_config: configuration is completed
[Tue Sep 16 10:25:17 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:17 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:17 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:17 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:17 2003] - open_logs : process 1128 is born to reproduce
[Tue Sep 16 10:25:17 2003] - post_config: configuration is completed
[Tue Sep 16 10:25:19 2003] - open_logs : process 956 is born to reproduce
[Tue Sep 16 10:25:19 2003] - post_config: configuration is completed
[Tue Sep 16 10:25:19 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:19 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:19 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:19 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:20 2003] - open_logs : process 956 is born to reproduce
[Tue Sep 16 10:25:20 2003] - post_config: configuration is completed
[Tue Sep 16 10:25:21 2003] - child_init : process 956 is born to serve
[Tue Sep 16 10:25:36 2003] - child_exit : process 956 now exits
[Tue Sep 16 10:25:36 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 956 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 1128 is shutdown
[Tue Sep 16 10:25:36 2003] - END : process 1128 is shutdown
(Don't you just love the way in which Windoze immediately re-uses the same PID?)
There seems to be slight excess of END's in there too!
Good / bad / don't-know?
Totally unexpected, try that quickly hacked version of say() so we can see the threads as well.
sub say { my($caller) = (caller(1))[3] =~ /([^:]+)$/; my $tid = APR::OS::thread_current(); if (defined $log_fh) { printf $log_fh "[%s] - %-11s: [%s] %s\n", scalar(localtime), $caller, $$tid, $_[0]; } else { # when the log file is not open warn __PACKAGE__ . " says: $_[0]\n"; } }
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.
- Steve
--------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
