I have two instances of the same Java program that talk to each other through a socket. They run on the same host. One waits for the other to receive a packet of data, after which this process is reversed. This constitutes a cycle interval.

The output of both instances is configured to give me some information about how long it takes to complete one of these cycles. A snippet of output from one of them follows:

Total interval duration: 85,120,197 nanoseconds.
                   Before receiving              5,239     0%
                    After receiving         83,174,365    97%
                      After sending          1,931,094     2%
                                End              9,499     0%

The percentages are of course out because I merely cast the derived doubles to an integer without rounding. This is not the problem.

The problem is that I am wondering why, when the two instances are running copies of the same program, would these instances dwell for about 97% of the time on an operation that involves blocking on a read statement from the socket they share.

As shown, the two instances take about 80 milliseconds to complete one cycle interval (about 12 cycles a second). I think this is far too long, as I have seen much shorter times before now, but I have recently made extensive changes to the program, and I think something I have put in these changes is causing the latency blowout. At the moment, I believe that whatever is doing this may also be responsible for the apparent simultaneous blocking anomaly.

The code that both instances execute where the blocking occurs is summarised here:

public final Transmitter receive(){
    Transmitter tr=null;
    try{
        Receiver.currentReceiver().measure("Before receiving");
        tr=(Transmitter)this.getInputStream().readObject();
        Receiver.currentReceiver().measure("After receiving");
    }catch(IOException x){
        //...
    }
    
    return tr;
}

The receive method cited in the above code fragment is executed by a Receiver - a type of java thread - customised to complement and be accessible from the code it is executing. This receive method is a member of a class that extends the Java socket class; it reads a Transmitter object passed from the instance at the other end of the socket connection. The receiver thread is retrieved in a way similar to the way one might retrieve the current thread: through the call to the Receiver class's static method currentReceiver. The measure method records a place in the code where a measurement of execution time will be taken. The string given to the measure method appears in the cycle time output disclosed at the top of this question.

It seems reasonable that both instances should not simultaneously be blocked on the same socket for what appears to exceed 90% of the time. One of the instances would block reading it while the other is doing the things necessary to eventually write to it; I think it reasonable to see one instance blocked for perhaps a bit more than half the time, but I observe there is a large window of time where both are blocked. What could be happening in that window, and how might I reduce or eliminate it?

Any ideas perhaps?

CodePudding user response：

Would have been nice if someone who lurks on this site could have helped, but this question might have valuable information. I'm sure someone can change this answer to conform to this site's standards.

Turning TCP_NODELAY on appears to halve the cycle interval, yet the proportion of time blocking on read is still about 97% - it's just half as long which is an improvement, but I would expect this proportion to perhaps begin with a 5, possibly a 6.