Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Threads, systemd, rsyslogd, and printf

Thu Aug 02, 2018 9:29 pm

I have a rather complex multi--threaded application written largely in c++. It runs as a systemd daemon using rsyslog for logging all console output to a log file. The console output is generated using printf from numerous places throughout the code, including the multiple threads. While the application itself runs flawlessly, I am having problems with the logging. If I start the daemon in the foreground ALL logging output comes out to the console perfectly every time. But when I let systemd start the daemon, the log files is sometimes either missing some lines, or, occasionally, missing entirely.

I would have expected if this was a threading issue that I would see the same behavior regardless of whether I start the daemon myself, or let systemd start it. But, that is not the case. I have NEVER seen any output missing when running the daemon manually as a foreground process. But there is often some output missing when started with systemd. And inane changes in the source code seem to affect how the logging behaves.

This is, I think, the last issue I have with this whole application, so I'd really like to get it resolved. Any ideas how to get to the root of the problem?

Regards,
Ray L.

Heater
Posts: 9721
Joined: Tue Jul 17, 2012 3:02 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 5:49 am

I would expect that multiple threads writing to the same resource, stdout in your case, at the same time would get into a mess. That is a race condition.
...inane changes in the source code seem to affect how the logging behaves.
Yep, sure sign of race conditions.

You need some kind of message queue to serialize all those log writes.

Of course wrapping mutual exclusion around many log writes may well kill performance.

A quick google search for "c++ logging threads" will find a ton of discussion and many solutions to this problem.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 2:09 pm

I have done lots of Googling, which has only further muddied the waters. It seems SOME Linux implementations are POSIX compliant, and the stdio calls themselves will handle locking of shared resources, making them thread-safe. Some apparently are not. Hence my question - what does Raspbian do? Obviously I can push everything through a single log queue (as I've done in other non-Linux-based applications), but that would be a large change, given the size of this project (40+ source files), and the hundreds of printf calls already in there. I'm hoping, perhaps in vain, that there might be a less intrusive option.

Regards,
Ray L.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 5:02 pm

The other thing that confuses me is that if it is a threading problem, I would expect to see problems when logging direct to the console, but I never have, not once. It seems to me it is the interaction with the syslog daemon that is the problem. The syslog daemon should be simply re-directing stdout/stderr, and, given it's entire raison d'etre, it SHOULD, from the applications POV, be indistinguishable from the console I/O streams.

Regards,
Ray L.

jahboater
Posts: 2858
Joined: Wed Feb 04, 2015 6:38 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 5:13 pm

Jagboy wrote:
Fri Aug 03, 2018 5:02 pm
The other thing that confuses me is that if it is a threading problem, I would expect to see problems when logging direct to the console, but I never have, not once.
It may be that logging direct to the console is unbuffered.
Multiple threads or tasks with their own private stdio buffers is always an issue.
You never know when they will be flushed.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 5:32 pm

AARRRRGGGGHHHH!!!! I made the below post a few minutes ago, and it disappeared!!! Here we go again:

Would this work?

Create a new global function logprintf.

logprintf would provide the same I/F as printf
logprintf would:
malloc a buffer
use vsprintf to format the log string into the buffer
launch a new thread, passing it the buffer
return to caller

the new thread would:
wait to acquire a global mutex granting it exclusive access to the console
write the buffer to the console
free the buffer
terminate the thread

This would be easy to implement, since logprintf would be a very short function (20 lines of code?). The changes to the main code would be limited to a global search/replace of printf with logprintf. This would ensure the console/rsyslog were only ever dealing with a single thread at a time. The volume of log output is generally small, so I cannot see this ever generating a large number of threads, or using a large amount of memory for the buffers. Any waiting would occur in the "worker" threads, not the main application.

Would that work? Anything I'm missing?

Regards,
Ray L.

Heater
Posts: 9721
Joined: Tue Jul 17, 2012 3:02 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 6:39 pm

Personally I would not want to be launching a new thread for every log message. That is wasteful.

Perhaps fire up a logger thread at program start up.

That logger thread would have a "logprintf " function that would do all the mutual exclusion so that the the other threads that call it get all their messages queued up cleanly. It would then print the queue to stdout.

My logprintf would also have a parameter for INFO, ERROR and other such message criteria so as to be able to control the amount of output.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 7:17 pm

Personally I would not want to be launching a new thread for every log message. That is wasteful.
Is it really? The whole point of pthreads is they are lightweight, low overhead. My logprintf is certainly simpler to implement than a single logging thread, and guarantees no waiting for the application threads that call it. For something that would happen, at very worst, a few dozen times in any given second, the overhead seems to me pretty insignificant. I already launch a new thread to process each packet I send/receive over the TCP/IP sockets I use to communicate between the nodes of the system, and I've seen zero performance or resource issues from that, which certainly is far higher overhead than the logging.

Regards,
Ray L.

Heater
Posts: 9721
Joined: Tue Jul 17, 2012 3:02 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 8:08 pm

Quite so. pthreads are pretty light weight. Still, spinning up a thread and all that context switching is more work than than not doing so.

If you have a working solution and performance to spare then why not go with it.

I'm not sure I agree with your statement that "guarantees no waiting for the application threads that call it."

At the end of the day you have many threads throwing data down a single "pipe". If the pipe cannot keep up then at some point queues/buffers/memory somewhere will become full and somebody has to wait. Or you throw the data away.

Given your apparently low demands on logging I guess this is not an issue.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Fri Aug 03, 2018 9:54 pm

Yes, if this were really spewing a lot of data, I'd go with your approach. But given the low logging bandwidth, if I ever run out of resources, I have MUCH bigger problems.

I'll see if I can get it implemented later today, and let you know how it works out.

Thanks for the input!

Regards,
Ray L.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Sat Aug 04, 2018 3:43 am

I'd REALLY like to be able to say the change improved things, but it really didn't! Still work perfectly when printing direct to the console, but is still messed up when printing through systemd/rsyslog. Below is the new code I added - could hardly be any simpler:

Code: Select all

static sem_t		LogMutex;

void logprintf_init(void)
{
	sem_init(&LogMutex, 0, 1);
}


void *LogThreadHandler(void *s)
{
	sem_wait(&LogMutex);
	printf((char *)s);
	free(s);
	sem_post(&LogMutex);
}


int logprintf(const char * format, ...)
{
#define BUFSIZ 256
	char *buf = (char *)malloc(BUFSIZ);
	va_list args;

	if (buf == NULL)
	{
		// No buffer, so do nothing
		return 0;
	}

	// Format the string
	va_start(args, format);
	vsnprintf(buf, BUFSIZ, format, args);

	// Spin off new thread to output the formatted string
	pthread_t handler;
	pthread_create(&handler, NULL, LogThreadHandler, (void *)buf);
	pthread_detach(handler);

	// Done!
	va_end(args);
	return 0;
}
Every call printf in the entire program was replaced with a call to logprintf. It works flawlessly writing direct to the console, and the performance is outstanding - very low latency, and I always get full lines of output. When started with systemd, output is often delayed, or blocked, until the next large block of output shows up. The result is I can rarely see the most recent output, without doing something to force MORE output to be printed. Even when I terminate the daemon (with systemctl), the most recent output, as much as hundreds, or perhaps thousands, of characters, often simply never appears.

I have to believe there is something about rsyslog that is screwing me, but I don't have a clue how to resolve it.

Regards,
Ray L.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Sat Aug 04, 2018 4:59 am

I think the next step is to do as suggested, and have logprintf queue the messages, and send them to stdout in the foreground task. Though, I don't understand why the current approach does not work...

Regards,
Ray L.

ejolson
Posts: 1842
Joined: Tue Mar 18, 2014 11:47 am

Re: Threads, systemd, rsyslogd, and printf

Sat Aug 04, 2018 6:42 am

Jagboy wrote:
Sat Aug 04, 2018 4:59 am
I think the next step is to do as suggested, and have logprintf queue the messages, and send them to stdout in the foreground task. Though, I don't understand why the current approach does not work...

Regards,
Ray L.
To clarify what was said earlier but ignored, after each printf insert

fflush(stdout);

to flush the buffers.

Are you compiling with the -pthread flag?

jahboater
Posts: 2858
Joined: Wed Feb 04, 2015 6:38 pm

Re: Threads, systemd, rsyslogd, and printf

Sat Aug 04, 2018 1:53 pm

Or

setbuf( stdout, NULL )

to switch off buffering permanently.

stderr is always unbuffered.

see "man setbuf" for details.

Jagboy
Posts: 17
Joined: Thu Dec 28, 2017 5:19 pm

Re: Threads, systemd, rsyslogd, and printf

Sat Aug 04, 2018 5:12 pm

To clarify what was said earlier but ignored, after each printf insert

fflush(stdout);

to flush the buffers.

Are you compiling with the -pthread flag?
You are right, I managed to miss that, and it does appear to solve the problem!

I am leaving the multi-threaded logprintf in place, as it seems to perform a bit better than either using raw printf, or the message queuing version. Much more testing to do, but it appears to be working properly for the first time!
Or

setbuf( stdout, NULL )

to switch off buffering permanently.

stderr is always unbuffered.

see "man setbuf" for details.
That is one I was not aware of. I will keep that in mind!

Thank you all for the great help! This is a BIG load off my mind! It's a real relief to have this (seemingly) working properly for the first time.

Regards,
Ray L.

Return to “C/C++”

Who is online

Users browsing this forum: No registered users and 10 guests