CODEWITHSUNDEEP
javajvmreal-timedelaynonblocking
Arslan Mehboob
Arslan Mehboob

Reputation: 1020

Java delay in execution between non-blocking statements

I have come upon a strange issue in one of our Java programs. Once in a while randomly some threads are delayed for up to 25 seconds in execution. This happens for 1-2 minutes and then the application is back to normal processing. It is a telephony application with strict time requirements so this is not acceptable.

Calling Class

    OCSIHandling ocsiHandler = new OCSIHandling(this.arg0);
    ocsiHandler.run();

Constructor

    public OCSIHandling()
    {
    //This is the last statement of the constructor after initializations
            logger.info("[" + refId + "][OCSI] SMS IDP");
    }

Class method 

    run(){
    //This is the first statement of the method which is executed with delay
    logger.info("[" + refId + "][OCSI] in run()");
    }

Sample log during issue

INFO 2014-02-07 06:03:27,674 [Thread-143840672] 100 - [MGW070214060327d384][OCSI] SMS IDP INFO 2014-02-07 06:03:49,771 [Thread-143840672] 123 - [MGW070214060327d384][OCSI] in run()

There is a delay in execution, 49-27 = 22 seconds

Program is running with -server option with a 32 bit HotSpot server VM. During this time the logging is messed up chronologically as well. 1:00:01 time stamp written before 1:00:00 and so. There is no thread pool.

We are using centos 5.4, 64-bit on a vmware client. Application is cpu intensive and there is not much memory requirement(its running with default heap size of 1GB) so I am not sure if GC can cause this much delay.

Logback file: http://pastebin.com/fpxYBYew

Please point me to what possible factors can lead to this kind of behaviour.

Edit: This happens in off peak

Upvotes: 0

Views: 539

Answers (1)

erickson
erickson

Reputation: 269647

Could you be running into a garbage collection issue? Add the following options to the java command when running your program (these would be included before the main class name, or before the -jar option): -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

This will cause detailed information about the garbage collector performance to be printed to the console (you may need to redirect output to a file). There are free programs available to analyze the output, but in your case, just looking for full garbage collections and checking the time they take might suffice.

Upvotes: 1

Related Questions