Hi. I use Boost::Threads to put multithreading in my own logging library, basically it puts writing to the file in a separate thread. Here is a code excerpt (simplified for brevity):

// this is the public member function used to actually start writing the log
void
ListenerToFile::onLog(std::string msg)
{
	// this will basically run the other function (ListenerToFile::onLogThread)
	// in a separate thread, with the msg string supplied
	boost::thread logThread( boost::bind(&ListenerToFile::onLogThread, this, msg) );
}


// mFileStream is a std::ofstream
// mMutex is a boost::mutex
// this is a private member function called only by ListenerToFile::onLog
void
ListenerToFile::onLogThread(std::string msg)
{
	// this effectively locks the usage of mFileStream
	// for the duration of this function
	// call (scoped_lock unlocks in its own destructor)
	boost::mutex::scoped_lock lock(mMutex);

	mFileStream.open(
		mFilename.c_str(), std::ios_base::out | std::ios_base::app);
	mFileStream << msg << '\n';
	mFileStream.close();
}

However I'm wondering if this is overkill? The overhead might make it slower than if its single-threaded. I am only outputting a single line of log message. On the other hand, I see it may help in situations wherein if the hard drive is very busy, if it was single-threaded, the whole program would be forced to wait to get a chance to do file i/o, but if its multi-threaded, the thread that writes to the file (namely ListenerToFile::onLogThread) would be the only one to wait and the program can move on without delay. Am I making sense? [Edited by - anomalous_underdog on November 1, 2008 9:02:35 AM]

Quote:Original post by anomalous_underdogOn the other hand, I see it may help in situations wherein if the hard drive is very busy, if it was single-threaded, the whole program would be forced to wait to get a chance to do file i/o

Don't worry, your OS and your runtime library already buffer I/O, so that it doesn't block your program for ages.

Quote:Original post by anomalous_underdog
However I'm wondering if this is overkill?

I think so.

logs are often useful when an application crashes. If you use a log thread the most useful messages (the latest ones) may not appear in the log because they was waiting in the thread queue while the crash happened. The messages may also appear in wrong order.
While debugging you want the log mechanism to work properly and the release version shouldn't create big log files anyway thus there is no reason to worry about the speed.

If you are gathering statistical information like fps, draw calls,... over time (a lot of non critical data) you don't need to open and close the file for every message.

Quote:However I'm wondering if this is overkill? The overhead might make it slower than if its single-threaded. I am only outputting a single line of log message.

Stop worrying about overhead and think about the importance of logging.

When you commit a log, do you need to make sure that log was written or not? A simple scenario - your application logs 15 messages indicating the status of initialization. Right after 15th message is logged, application crashes. Since logging is asynchronous, only 3 logs were written to file, leaving you with either invalid or inadequate information about what went wrong.

Quote:basically it puts writing to the file in a separate thread.

Thread per log is a disaster. You're basically spawning one thread each time you log something, without checking the progress of the thread. Then, the handlers lock on mutex.

Under load, you will spawn multiple threads all destined to lock on same mutex. Since file access is slower than spawning of threads, program will continue, keep spawning more threads, resulting in rapid consumption of system resources.

Even worse, you allocate logThread in function scope. I'm not sure about details of how boost handles this, but that seems unusual. Also, boost::function has huge overhead for such fine granularity, short life-span pointers.


If your logs are optional (you don't care if they are lost), then use periodic logging in separate thread. Have thread-safe list of log entries to which you put logs to be writted. Then have logging worker that periodically polls the list and writes all logs to disk.

But again, unless you have a very specific reason, there's little justification to go through overhead of inter-thread communication just to write logs.

See the Services section for a slightly more robust solution (again, use custom function pointers instead of boost bind).

Quote:Original post by Kambiz
logs are often useful when an application crashes. If you use a log thread the most useful messages (the latest ones) may not appear in the log because they was waiting in the thread queue while the crash happened.

I've experienced situations in other projects where the last log message (like an assert failure message) never got printed in the log file even though it was single-threaded. The message got displayed in the standard output (the console), but not in the log file, although I'm guessing it was because of the design of the engine I use in that one.

Quote:Original post by Kambiz
The messages may also appear in wrong order.

I'm fine with messages appearing out of order.

Quote:Original post by Kambiz
While debugging you want the log mechanism to work properly and the release version shouldn't create big log files anyway thus there is no reason to worry about the speed.

I see, thanks for the advice

Quote:Original post by Kambiz
If you are gathering statistical information like fps, draw calls,... over time (a lot of non critical data) you don't need to open and close the file for every message.

I've had experiences in Windows wherein if the file handle is left open while the program is running, other programs like Notepad wouldn't be allowed to open the file. Windows throws an error like "Cannot open file.log. The file is being used by an external process."




Well thanks for the explanations guys. Guess I'll throw the multithreading out the window then. Good thing I asked here first before moving on =)