Logger class -> write to file too slow

Souldrift

Hi there, I built a logger class to trace and debug my programs. Now I have very real-time dependent programs here and the problem is, when I activate the logger´s 'log to file'-option the program gets too slow to be run properly. But I want/need the logger to be active in normal operation, as well ... so that I can have a look at the output if something went wrong (like a crash). The time stealer seems to be the opening and closing of the file for every log entry. But I cannot simply open it once and never close it, because the log entrys are only put into the file with the close() call. This is the logger (which works otherwise fine). Any help with speeding it up, restructuring it or whatever needs to be done is appreciated. :)

Logger::Logger(void)
{
m_iLogLevel = DEBUG;
m_bToConsole = true;
m_bToFile = false;
m_sFilename = "tts_dump.out";
m_sPath = "./";
m_bFirstWriteToFile = true;
}

Logger::~Logger(void)
{}

Logger* Logger::GetInstance()
{
if( m_pLogger == NULL )
{
m_pLogger = new Logger();
}
return m_pLogger;
}

void Logger::Out( int level, const char* pcszFormat, ... )
{
va_list ap;
va_start( ap, pcszFormat );

if( m\_bToConsole )
{
	if( pcszFormat && level <= m\_iLogLevel )
	{
		vprintf( pcszFormat, ap );
	}
}

if( m\_bToFile )
{
	if( pcszFormat && level <= m\_iLogLevel )
	{
            	string loc = m\_sPath;
		loc.append( m\_sFilename );

		if( m\_bFirstWriteToFile )
		{
			m\_oFile.open(loc.c\_str(), ios::out);
			m\_bFirstWriteToFile = false;
		}
		else
		{
			m\_oFile.open(loc.c\_str(), ios::out|ios::app);
		}

		if( !m\_oFile ) 
		{
			cerr << loc << " kann nicht geöffnet werden!\\n";
		} 

		char buffer\[1024\];
		
		vsprintf\_s( buffer, pcszFormat, ap );

		m\_oFile << buffer;
		m\_oFile.close();
	}
}
va\_end( ap );

}

void Logger::SetLogLevel( int level )
{
if( level >= 0 && level <= SYS_ERROR )
m_iLogLevel = level;
}

void Logger::SetConsoleOutput( bool on )
{
m_bToConsole = on;
}

void Logger::SetFileOutput( bool on, string filename, string path )
{
m_bToFile = on;
}

Cheers Souldrift

Stuart Dootson

I'd suggest rewriting it so that you don't need to close it to write items to the file - you've identified opening the file as the hotspot, so remove the sdcenario that means you have to open it so often. The std::basic_ostream::flush()[^] method could prove useful, to ensure the message is actually pushed to disk.

Java, Basic, who cares - it's all a bunch of tree-hugging hippy cr*p

Cedric Moonen

Souldrift wrote:

The time stealer seems to be the opening and closing of the file for every log entry. But I cannot simply open it once and never close it, because the log entrys are only put into the file with the close() call.

Even when you flush the data to the file (calling the flush method) ?

Cédric Moonen Software developer
Charting control [v2.0] OpenGL game tutorial in C++

Michael Schubert

Create a buffer in memory, for example a string array, collect your data in this array for a certain amount of time (or a certain number of entries) and then write the contents to the file in one go.

David Crow

File I/O, especially opening, is very expensive. You may want to implement it in a separate thread so that the primary thread can run unimpeded.

"Old age is like a bank account. You withdraw later in life what you have deposited along the way." - Unknown

"Fireproof doesn't mean the fire will never come. It means when the fire comes that you will be able to withstand it." - Michael Simmons

Joe Woodbury

Get rid of buffered I/O calls. Use either purely native calls (CreateFile()) or at least the CRT open function. If that's still too slow, using asynchronous writes (yes, they are tricky, but they do work.) Do understand that you may need a mechanism to throw away messages else you're logging could get permanently behind. An alternative is to write log string to a buffer and when it passes 4k, do an asynchronous write.

Chuck OToole

The bad news is that if you are using a Logger Class to dump output somewhere in case your program crashes, then Open / Append / Close is the only way to make sure that critical "trace" messages are not left in memory at the crash. All the other suggestions, buffering, asynch I/O, can improve the speed at the expense of the exact reason to have a logger for debug tracing. Bite the bullet and live with the slower code. Here's what I use which includes a timestamp in the output, modify it as you see fit. Also, since this is in a class derived from a synchornized object (which has a Lock/Unlock function), this is threadsafe.

// Add a line of text to the Log
void Logger::LogThis(CString Text)
{
SYSTEMTIME cur_time;
CString t1;
CString t2;
DWORD dwBytesWritten;

if (Folder.IsEmpty() || Prefix.IsEmpty())
{
	TRACE("Log Location Not Set");
	return;
}
Lock();													// force single file to the log file
GetLocalTime(&cur\_time);
t1.Format("%02d-%02d-%04d %02d:%02d:%02d : %.200s\\r\\n",
	      cur\_time.wMonth, cur\_time.wDay, cur\_time.wYear,
	      cur\_time.wHour, cur\_time.wMinute, cur\_time.wSecond, Text);
t2.Format("%s%s%04d%02d%02d.log", Folder, Prefix, cur\_time.wYear, cur\_time.wMonth, cur\_time.wDay);
HANDLE hAppend = CreateFile(t2,	// open log file
		FILE\_APPEND\_DATA,		// open for writing
		FILE\_SHARE\_READ,		// allow multiple readers
		NULL,				// no security
		OPEN\_ALWAYS,			// open or create
		FILE\_ATTRIBUTE\_NORMAL,	// normal file
		NULL);				// no attr. template
if (hAppend != INVALID\_HANDLE\_VALUE)
{
	SetFilePointer(hAppend, 0, NULL, FILE\_END);
	WriteFile(hAppend, (LPCTSTR)t1, t1.GetLength(), &dwBytesWritten, NULL);
	CloseHandle(hAppend);
}
Unlock();												// OK, file is ready for the next guy

}

And it's created with:

TheLogFile = new Logger();
TheLogFile->SetFolder("Log\\\\");
TheLogFile->SetPrefix("UpdateProcess");

Souldrift

Thanks for all the answers (and the code). I came up with the buffering idea, as well - and I´m using it now. I only buffer 10 messages, then write. Seems to be enough to get rid of my real-time problems. Problem is I cannot simply 'bite the bullet', since the project is about audio streaming. And the stream is very corrupted when the logger opens a file every time. I also already built a locking mechanism. Now I´ll see about flushing the stream. If it doesn´t work I´ll have to live with the small buffer ... for now. Btw, are CreateFile() and WriteFile() significantly different from what I do? Ofstream open() and '<<' ? Thanks Souldrift

Michael Schubert

Souldrift wrote:

Btw, are CreateFile() and WriteFile() significantly different from what I do? Ofstream open() and '<<' ?

Using CreateFile() gives you all the control (Performance/Sharing/Security) the Win32 API has to offer.

Logger class -&gt; write to file too slow

Logger class -> write to file too slow