I was wondering if anyone could possibly shed some light on a runaway
thread problem.
I have a logging system where many threads write log messages to a pipe, and a logging thread reads from this pipe, and then writes the message to a file.
During normal operation, this system takes 1-5% of the processor, but occasionally (at unpredictable times) it goes berserk, and takes up 45-55% of the processor, which causes all sorts of problems. When it is in this state, the system (
tomcat) must actually be killed (kill -9). This has only started occurring since the addition of the logging system/thread - and so it is my belief that the logging thread somehow gets into a state which causes it to stop reading from the pipe, and whatever it is doing it spiking the processor.
I believe that this has something to do with the FileWriter blocking on write(), or the pipe blocking on read. Of course, I suppose it could also be an odd synchronization problem.
I have been tracking this for a week and I can't seem to find a solution. Does anyone have any ideas?
There is a lot of code in this system, but below are what I believe are the relavent parts...
<code>
protected LogManager()
{
// initialize the pipes
try
{
outPipe = new PipedOutputStream();
inPipe = new PipedInputStream(outPipe);
outBuffer = new BufferedWriter(new OutputStreamWriter(new DataOutputStream(outPipe))); // wrap the pipe with a writer
inBuffer = new BufferedReader(new InputStreamReader(new DataInputStream(inPipe))); // wrap the pipe with a reader
}
catch (Exception ex)
{
System.out.println("Failed to initialize pipes in LogManager constructor");
pipeInitSuccessful = false;
}
}
</code>
This is the method used by client threads to write to the log..
<code>
public static void log(int logLevel,
String sourceClass, String sourceMethod, String msg)
{
try
{
if (!isInitialized()) { return; } // ensure the logger is ready for a message before sending one
try { sleep(3); } // force main thread to sleep in case it is hogging processor
catch (Exception ex) { } // the thread was interrupted while it was sleeping
// check if there are newlines, replace them with ~ if found, so they can be xferred via pipe
msg = cleanString(msg);
sourceClass = cleanString(sourceClass);
sourceMethod = cleanString(sourceMethod);
synchLog(logLevel, sourceClass, sourceMethod, msg); // all signs say go for logging to the pipe
}
catch (Exception ex)
{
// print an error and stop any further log messages
System.out.println("LogManager.log(): exception thrown trying to log message" + ex);
setInitialized(false);
}
}
public static synchronized void synchLog(int logLevel, String sourceClass, String sourceMethod, String msg)
{
try
{
outBuffer.write(String.valueOf(logLevel) + "\n"); // send the log level to the log manager
outBuffer.write(sourceClass + "\n"); // send the source class to the log manager
outBuffer.write(sourceMethod + "\n"); // send the source method to the log manager
outBuffer.write(msg + "\n"); // send the message to the log manager
outBuffer.flush(); // flush to make sure that the values are written to the pipe
}
catch (Exception ex)
{
// print an error and stop any further log messages
System.out.println("LogManager.synchLog(): exception thrown trying to write to pipe " + ex);
setInitialized(false);
}
}
</code>
The run method for the thread...
<code>
public void run()
{
if (!pipeInitSuccessful) { return; } // check to make sure that the inbuffer was initialized properly
if (!hasListeners()) { return; } // if there are not any listeners, then you won't be able to add them after the manager is running...
isMgrStarted = true;
isInitialized(true);
try
{
while (!interrupted())
{
// check the pipe...
if (inBuffer.ready())
{
pipeReadAndLog();
}
//sleep to allow other threads to run
sleep(5);
}
}
catch (InterruptedException ex)
{ // thread was interrupted during sleep or wait, this is a signal for the log to die
// if there is anything left in the pipe, log it, and then die.
try
{
System.out.println("LogManager: cleaning out residual log messages in pipe...");
int i = 0;
boolean readMoreFromPipe = true;
while ( (inBuffer.ready()) && (readMoreFromPipe) )
{
i++;
pipeReadAndLog();
if (i > maxResidualEntries) {readMoreFromPipe = false;} // do not sit here forever
}
}
catch (Exception innerEx)
{
System.out.println("LogManager.run(): Exception while trying to clean out residual log messages in pipe..." + innerEx);
}
}
catch (Exception ex)
{
// some other exception was thrown, meaning an error..., so print a message and then stop the log from continuing to run.
System.out.println("LogManager.run(): Exception thrown while reading and logging messages: " + ex);
setInitialized(false);
}
finally
{
// make sure that the other listeners are ended properly if the urn method bombs, or when the Log thread is told to close
// so that the logs are closed properly and not left in a junk state
end();
}
}
</code>
The method which writes the message to the file:
<code>
private boolean writeToFile(String msg)
// This method will just attempt to write a string to the file, and log a message if it fails.
{
boolean successful = true; // flag indicating the success of the write
try
{
fw.write(msg + "\r\n");
fw.flush();
}
catch (IOException ex)
{
System.out.println("FileLogWriter:writeToFile() - Unable to write message to log '" + filePath + fileName + "' Exception:" + ex.getMessage());
successful = false;
}
return successful;
} // end writeToFile method
</code>