log4perl-devel

[log4perl-devel] A threading question

[John L. <joh...@gm...>]

Mike Schilli said:

> It would be great if you could provide test results / bug reports of
> running Log4perl with Perl threads, though.
>
> That being said, there are synchronization mechanisms for file
> appenders:
>
> http://log4perl.sourceforge.net/d/Log/Log4perl/FAQ.html#23804

I've tried using Log4perl in a multi-threaded server script and the
synchronized appender fails consistently after logging exactly 32768 lines,
with (piped through cat -v):

Thread 1 terminated abnormally: semop(1343496
^@^@^@^@^@^@^@^@^A^@^@^P) failed: Numerical result out of range  at
/usr/local/lib/perl5/site_perl/5.10.0/Log/Log4perl/Util/Semaphore.pm
line 192, <GEN3277> chunk 2.
semop(1343496 ^@^@^@^@^@^@^@^@^A^@^@^P) failed: Numerical result out
of range  at /usr/local/lib/perl5/site_perl/5.10.0/Log/Log4perl/Util/Semaphore.pm
line 192.

OS is CentOS 5.2 under xen.  In one case there were three threads.  Without
using the synchronized appender, in heavy testing overwrites occurred.  I'll
try to replicate the failure in my test environment (Kubuntu 8.04).

Regards, John

Re: [log4perl-devel] A threading question

[Mike S. <m...@pe...>]

On Sat, 8 Nov 2008, John Little wrote:

> I've tried using Log4perl in a multi-threaded server script and the
> synchronized appender fails consistently after logging exactly 32768
> lines, with (piped through cat -v): Thread 1 terminated abnormally:
> semop(1343496 ^@^@^@^@^@^@^@^@^A^@^@^P) failed: Numerical result out
> of range  at

Got it, it's not really related to threads, there was a bug in the
semaphore code that caused this, I've fixed it in CVS, it'll roll out
with the next release (1.20).

By the way, have you tried using the 'syswrite' option of the file
appender instead? It prevents overlapping messages as well and it's
easier to use than the synchronizing appender:

     log4perl.appender.Logfile.syswrite  = 1

     http://search.cpan.org/dist/Log-Log4perl/lib/Log/Log4perl/FAQ.pm#How_can_I_synchronize_access_to_an_appender

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] A threading question

[John L. <joh...@gm...>]

Mike

> Got it, ... , it'll roll out with the next release (1.20).

Thank you!

> By the way, have you tried using the 'syswrite' option of the file
> appender instead? It prevents overlapping messages as well and it's
> easier to use than the synchronizing appender:
>
>    log4perl.appender.Logfile.syswrite  = 1

No,  didn't know about that.  A colleague's been testing with the
synchronizer removed, at about 15 messages per second, with no
overwriting so far, which is what I'd expected on Linux initially.
The next restart will pick up the syswrite option above.

Which reminds me, I couldn't get init_and_watch($conf_file, 'HUP') to
work with threads, which is not surprising, given that perl threads
and signals don't mix very well.

Regards, John

Re: [log4perl-devel] A threading question

[Mike S. <m...@pe...>]

On Sat, 8 Nov 2008, John Little wrote:

> Which reminds me, I couldn't get init_and_watch($conf_file, 'HUP') to
> work with threads, which is not surprising, given that perl threads
> and signals don't mix very well.

Can you provide code to reproduce the problem? I'd be happy to track it
down.

-- Mike

Mike Schilli
m...@pe...

Re: [log4perl-devel] A threading question

[John L. <joh...@gm...>]

Mike

> Can you provide code to reproduce the problem? I'd be happy to track it
> down.

I haven't been able to reproduce the strife I was having; most use of
signals was failing.

However, there is the obvious.  My perl 5.10 is delivering all OS
signals to the 'main' thread, so the logger in it gets the HUP but not
the others (cloned from the first by the threads mechanism).  A simple
fix is:

Log::Log4perl->init_and_watch("dllog.conf", 'HUP',
                                {preinit_callback => \&propagate_hup} );
sub propagate_hup {
    for my $t (threads->list) { $t->kill('HUP'); }
    return 1;
}

I'll use this and report any trouble.

Regards, John

Re: [log4perl-devel] A threading question

[John L. <joh...@gm...>]

Mike, all,

> A simple fix is:
>
> Log::Log4perl->init_and_watch("dllog.conf", 'HUP',
>                                {preinit_callback => \&propagate_hup} );
> sub propagate_hup {
>    for my $t (threads->list) { $t->kill('HUP'); }
>    return 1;
> }

A little too simple upon reflection; I don't know why it didn't chase
its tail indefinitely.  Better:

my $main_tid = threads->tid;
sub propagate_hup {
    if (threads->tid == $main_tid) {
        for my $t (threads->list) { $t->kill('HUP') unless $t-> == $main_tid; }
    }
    return 1;
}

Regards, John

Re: [log4perl-devel] A threading question

[John L. <joh...@gm...>]

Hi

Of course, that should be

my $main_tid = threads->tid;
sub propagate_hup {
   if (threads->tid == $main_tid) {
       for my $t (threads->list) { $t->kill('HUP') unless $t->tid ==
$main_tid; }
   }
   return 1;
}

Regards, John