Solved

Synchronization Problem

Posted on 2002-06-20
9
214 Views
Last Modified: 2010-03-31
The following is a long explanation of a synchronization issue.  The main questions (at the end) are:
Has this been documented or experienced by others, and are there ways for thread control that can be used to replace synchronization?

I've encountered a problem with Java synchronization (I'm currently using JDK 1.3.1).  Here's a snippet of the Java class:

public class MasterGenerator
{
      private static String statusSyncObject = "";

      public boolean updateBook(Hashtable sessionHash, int status) throws DatabaseException
         {
                    Log.log(Log.DEBUG,"Inside MasterGenerator notify()");


            Log.log(Log.DEBUG,"Before sync block in updateBook");

            synchronized(statusSyncObject)
                {
                  Log.log(Log.DEBUG,"start of sync block in updateBook");

                  ServerSession session = (ReportBookServerSessionImpl)sessionHash.get(rbkey);

                  session.updateStatus(status);

                  Log.log(Log.DEBUG,"end of sync block in updateBook");
            }
      }
.
.
.
}

The application is usually very active, and a hundred or so instances of this class can be created with the updateBook method called every second.  Then the application just hangs (the majority of the application, that is, the part that is dependent on this routine).  My first suspicion was a synchronization problem; maybe with a deadlock, but in the code there was no deadlock possible.  Then I began to do timings within synchronization blocks, and with a heavy load what I found was that the handling of synchronization was very slow, taking many minutes between the exit of one thread and the start of the next.  Finally, I put logging statements in every synchronized block, like above, and waited for it to happen again.  The normal log would should something like this:

Inside MasterGenerator notify()
Before sync block in updateBook
start of sync block in updateBook
end of sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
start of sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
end of sync block in updateBook
start of sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
end of sync block in updateBook
...

which is perfectly okay. This pattern would repeat for days without problems, making up 99%+ of what is seen.  Then when the application hung again, I looked at the log, and the ending showed basically this:

Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook

basically every thread is waiting to get in.  Looking at the two calls between the logs, there is really no particular point in the code that should or could get stuck at (errors yes, but not stuck).   In addition, I put logs in those methods which shows them getting in and out of them (and in between).  But what's REALLY curious is before this pattern of hanging, I see something like this in the log file:

Inside MasterGenerator notify()
Before sync block in updateBook
start of sync block in updateBook
start of sync block in updateBook
end of sync block in updateBook
end of sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
Inside MasterGenerator notify()
Before sync block in updateBook
start of sync block in updateBook
start of sync block in updateBook
end of sync block in updateBook
end of sync block in updateBook
start of sync block in updateBook
start of sync block in updateBook
end of sync block in updateBook
end of sync block in updateBook

Basically this should never happen - there should never be two starts in a row (without an end in between), but this duplicate happened regularly for a little while in the log before hanging permanently.  By the way, the Log class is a simple custom class that opens a log file, appends to it, and closes the file for every log request.  The Log class itself uses a static synchronization method for those three steps plus a short sleep delay at the end of the method, so every thread that is logging will have to wait its turn.  Since it also uses synchronization, there is no guarantee that the log requests will appear in the order they were received, but it usually happens this way from my experience.  In any case, in this particular situation, the abnormality (double starts and ends) happened too regularly to be explained by random log synchronization timing.  I should also point on that the log file contains many other logs (I've only shown the logs from the code snippet), and logging did continue for other parts of the application where things were not hanging.

I am wondering whether this synchronization problem has been documented, or has anyone encountered a similar problem under heavy loads.  Also, is there another way for thread control without the use of synchronization?  Thanks in Advance.


0
Comment
Question by:jove
  • 2
  • 2
  • 2
  • +2
9 Comments
 
LVL 4

Expert Comment

by:kylar
ID: 7097503
Can you post the Log class/method too?

Kylar
0
 
LVL 4

Expert Comment

by:kylar
ID: 7097509
Is one of the methods:

ServerSession session = (ReportBookServerSessionImpl)sessionHash.get(rbkey);

session.updateStatus(status);

possibly throwing? Java will give up the syncronization lock as soon as the code goes outside the scope of the lock (either by ending the run or by exception).

Kylar
0
 

Author Comment

by:jove
ID: 7097656
Neither of those methods will throw exceptions up here - they're caught in try-catch blocks in their respective methods.

Here's a snippet of the Log class:

public static void log(int pMsgType, Object pMsgObject)
{
  if (pMsgType > minSeverity)
     return;
  ...
  writeLog(pMsgType, msg, logFileName, recordSource, showMilliSeconds);
}

private static synchronized void writeLog(int pMsgType, String msg, String pLogFileName, String pRecordSource, boolean pMilli)
  {
               
        PrintWriter p = null;
        FileOutputStream fos = null;

        if (pLogFileName.equals(""))
        {
         System.out.println(msg);
            return;
     }


        try
        {
            fos = new FileOutputStream(pLogFileName, true);
            p = new PrintWriter( fos );
        }
        catch( IOException e )
        {
                     System.err.println("LogFile: Exception: " + e.getMessage());
            try
            {
                if (p != null)
                    p.close();
                if (fos != null)
                    fos.close();
            }
            catch (IOException ioe) {}
           
            return;
        }

        try
        {
                  String msgHdr = buildMsgHeader(pMsgType, pRecordSource, pMilli);

                  StringTokenizer strtok = new StringTokenizer(msg,"\n",false);
                  String token = "";

                  while (strtok.hasMoreElements())
                     {
                         token = strtok.nextToken();
                   p.print(msgHdr);
                   p.println(token);
                     }
               
            p.flush();
              }
        finally
        {
            try
            {
                if (p != null)
                    p.close();
                if (fos != null)
                    fos.close();
            }
            catch (IOException ioe) {}

        }

    }
0
 
LVL 92

Accepted Solution

by:
objects earned 200 total points
ID: 7097754
Maybe an exception other that an IOException.
Plus you don't print out the exception in the second try/catch so if an exception was being thrown (resulting in nothing being written to the log) then you would not know about it.

I'd suggest printing out any exceptions that are caught plus something like the following jic:

  synchronized(statusSyncObject)
  {
     try
     {
        Log.log(Log.DEBUG,"start of sync block in updateBook");

        ServerSession session = (ReportBookServerSessionImpl)sessionHash.get(rbkey);

        session.updateStatus(status);
     }
     catch (Exception ex)
     {
        System.err.println(ex);
     }
     finally
     {
        Log.log(Log.DEBUG,"end of sync block in updateBook");
     }
  }
0
Better Security Awareness With Threat Intelligence

See how one of the leading financial services organizations uses Recorded Future as part of a holistic threat intelligence program to promote security awareness and proactively and efficiently identify threats.

 
LVL 92

Expert Comment

by:objects
ID: 7097886
0
 
LVL 9

Expert Comment

by:Venci75
ID: 7098042
are you sure that ther is no call to a wait() method in any of the:
Log.log()
ReportBookServerSessionImpl.get();
ServerSession.updateStatus();

methods?    
0
 

Author Comment

by:jove
ID: 7099037
I'll put a try/catch block on the synchronized block, and add messaging on the catch portions of the logging.  I don't think that this is the root of the problem, but it's a good idea anyway.  There is no call to the wait() method anywhere in the code.
0
 
LVL 35

Expert Comment

by:girionis
ID: 8860611
No comment has been added lately, so it's time to clean up this TA.
I will leave a recommendation in the Cleanup topic area that this
question is:

- points to objects

Please leave any comments here within the
next seven days.

PLEASE DO NOT ACCEPT THIS COMMENT AS AN ANSWER !

girionis
Cleanup Volunteer
0

Featured Post

Do You Know the 4 Main Threat Actor Types?

Do you know the main threat actor types? Most attackers fall into one of four categories, each with their own favored tactics, techniques, and procedures.

Join & Write a Comment

After being asked a question last year, I went into one of my moods where I did some research and code just for the fun and learning of it all.  Subsequently, from this journey, I put together this article on "Range Searching Using Visual Basic.NET …
Java Flight Recorder and Java Mission Control together create a complete tool chain to continuously collect low level and detailed runtime information enabling after-the-fact incident analysis. Java Flight Recorder is a profiling and event collectio…
Video by: Michael
Viewers learn about how to reduce the potential repetitiveness of coding in main by developing methods to perform specific tasks for their program. Additionally, objects are introduced for the purpose of learning how to call methods in Java. Define …
This theoretical tutorial explains exceptions, reasons for exceptions, different categories of exception and exception hierarchy.

743 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question

Need Help in Real-Time?

Connect with top rated Experts

13 Experts available now in Live!

Get 1:1 Help Now