Re: [syslog-ng] Program destination seems to block

17 May 2010

      OK, I finally got back to this. The strace is too large to send to this

I'm not an strace expert, but it looks source is no longer read, even though the

14:56:42.508034 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508067 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508099 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508133 poll([{fd=4, events=POLLIN}, 1 ([{fd=3, revents=POLLIN}]) <0.000005> 14:56:42.508180 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000005> 14:56:42.508214 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508246 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000005> 14:56:42.508279 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508311 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000005> 14:56:42.508344 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508376 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508416 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000005> 14:56:42.508449 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508481 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000005> 14:56:42.508514 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508546 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004> 14:56:42.508579 write(5, "-rwxr-xr-x 1 root root temporarily unavailable) <0.000004>

This just repeats over and over again.

Thanks for looking at this.

Balazs Scheidler wrote:

list, approx 1MB. like the source is polled, but once the output can not be written to, the poll shows data is available. 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource {fd=5, events=0}, {fd=6, events=POLLIN}, {fd=3, events=POLLIN}], 4, 304) = 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource 925 Jun 30  2009 mk_cmds\n", 55) = -1 EAGAIN (Resource
...
On Wed, 2010-04-14 at 14:04 -0700, Evan Rempel wrote:
...
Balazs Scheidler wrote:
...
On Wed, 2010-04-14 at 13:18 -0700, Evan Rempel wrote:
...
A little background.
There is a "server" syslog-ng process that accepts messages from the network and
sends the messages to a variety of destinations. For this report, I am only interested
in one destination that happens to be a pipe.
There is a "slave" syslog-ng process that reads from the pipe that the "server" writes to,
and writes to a program destination.
The program reads the standard in, and does "something".
All works well.
At some point our application (we know why and don't want to discuss it) application stops
reading standard in for a while (1,000,000 lines over an hour). We expect that the memory
footprint of syslog-ng "slave" to grow during this time but it does not. Instead, the
memory footprint of the syslog-ng "server" grows. When our application starts reading
its standard in again, the memory footprint of the syslog "slave" grows very quickly,
and all messages reach the destination.
I think that the syslog-ng "slave" get blocked on the program destination in a way that
prevents it from reading its source, resulting in the upstream syslog-ng "server" having
to buffer all of the messages.
There is no flow control anywhere, and both syslog-ng instances have log_fifo_size(8000000)
for all of the destinations.
Anyone have any suggestions?
Hmm, either the slave syslog-ng really blocks (but I don't know any
similar bugs right now), or flow control is enabled.
There was a bug that caused flow-control to be enabled, if any of the
flags was used. Do you have fallback enabled?
No, the only flags in the "slave" is no-parse.
...
Can you post the exact versions of syslog-ng you are using?
3.0.5 OSE
...
Also, you could confirm if the slave instance really blocks, or it has
just stalled one of its sources. You could do that by attaching to the
slave process using strace for a little while.
1) first check what fd is being used between master/slave (lsof -p
<pid>)
2) then check via strace if that fd is being polled for POLLIN or not
If it is not polled, then flow-control is somehow enabled, if syslog-ng
is not polling but waiting somewhere, then it might be blocked as you
suggest.
Anyway, the list of open file descriptors and the strace dump could help
in tracking down both cases.
Not to be lazy here, but I am not going to get to this for weeks, really busy
at my site right now.
Here is a program that can turn on/off the reading of standard in by using
kill -USR1 <PID>
kill -USR2 <PID>
---------------
#!/usr/bin/perl
my $read = 0;
$SIG{USR1} = sub { $read = 1 };
$SIG{USR2} = sub { $read = 0 };
while ( not eof(STDIN)) {
   if ( $read == 1 ) {
     $line = <STDIN>;
     print $line;
   } else {
     sleep 1;
   }
}
---------------
So hopefully you can reproduce this this really easy at your end.
If I don't hear back, in a few weeks I'll get to this.
I've tried it with 3.1.1, 3.0.6 and finally 3.0.5 and all behaved
properly. Memory size grew until it couldn't write to the test program,
of course only until the FIFO size filled up.
Once I let the program go with a SIGUSR1 it started sending messages,
the drop count stayed the same. Flow-control was not enabled.
-- 
Evan Rempel                               erempel@uvic.ca
Senior Systems Administrator                 250.721.7691
Unix Services, University Systems, University of Victoria

-- 
Evan Rempel                               erempel@uvic.ca
Senior Systems Administrator                 250.721.7691
Unix Services, University Systems, University of Victoria

Evan Rempel

tags

participants (1)