Solved

Synchronization Problem

Posted on 2002-06-20
9
216 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
Courses: Start Training Online With Pros, Today

Brush up on the basics or master the advanced techniques required to earn essential industry certifications, with Courses. Enroll in a course and start learning today. Training topics range from Android App Dev to the Xen Virtualization Platform.

 
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
 
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

Announcing the Most Valuable Experts of 2016

MVEs are more concerned with the satisfaction of those they help than with the considerable points they can earn. They are the types of people you feel privileged to call colleagues. Join us in honoring this amazing group of Experts.

Question has a verified solution.

If you are experiencing a similar issue, please ask a related question

Suggested Solutions

Title # Comments Views Activity
ForLoop Example 3 48
Way to decrease size of apk file 9 65
hibernate jars 4 28
Tomcat: Unable to run tomcat service. 2 18
By the end of 1980s, object oriented programming using languages like C++, Simula69 and ObjectPascal gained momentum. It looked like programmers finally found the perfect language. C++ successfully combined the object oriented principles of Simula w…
In this post we will learn how to connect and configure Android Device (Smartphone etc.) with Android Studio. After that we will run a simple Hello World Program.
Viewers learn about the “for” loop and how it works in Java. By comparing it to the while loop learned before, viewers can make the transition easily. You will learn about the formatting of the for loop as we write a program that prints even numbers…
Viewers will learn one way to get user input in Java. Introduce the Scanner object: Declare the variable that stores the user input: An example prompting the user for input: Methods you need to invoke in order to properly get  user input:

808 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