Java readObject from Inputstream taking up 50% of CPU

Question

I am running into a weird problem where this thread which reads from an inputstream, specifically readObject. The thread is blocking on the call like it is suppose to because I have tried putting log debugging statements and it shows its blocking. The problem is this thread is still marked as running in the profiler and it takes up 50% of my cpu usage. I have a similar thread to this which blocks properly and when blocked takes up 0% cpu. I am baffled at what can be going wrong here.

Since I am a new user I can't post image, please see. Green in the image means running, yellow is blocked or waiting.

Image also available unscaled here:

Main

  {
    SocketFactory factory = SocketFactory.getDefault();
    Socket tcpSocket = factory.createSocket("localhost", 5011);
    IoTcpReadRunnable ioTcpReadRunnable = new IoTcpReadRunnable(new MessageProcessor()
    {
        @Override
        public void enqueueReceivedMessage(Object message)
        {
            System.out.println("MessageReceived Enqueued.");
        }

        @Override
        public void enqueueMessageToWrite(Envelope message)
        {
            System.out.println("Message Enqueued to Write.");
        }
    }, tcpSocket);

    new Thread(ioTcpReadRunnable, "ClientExample IoTcpRead").start(); 

}

TcpRead Runnable

public final class IoTcpReadRunnable implements Runnable {
public static final Logger logger = LoggerFactory.getLogger(IoTcpReadRunnable.class);
protected MessageProcessor<MessageType> messageProcessor = null;
protected Socket tcpSocket = null;
protected ObjectOutputStream outputStream = null;
protected ObjectInputStream inputStream = null;
protected boolean connected = false;

public IoTcpReadRunnable(MessageProcessor<MessageType> messageProcessor, Socket tcpSocket)
{
    this.messageProcessor = messageProcessor;
    this.tcpSocket = tcpSocket;
    this.init();
}

protected void init()
{
    try
    {
        this.outputStream = new ObjectOutputStream(tcpSocket.getOutputStream());
        this.outputStream.flush();

        this.inputStream = new ObjectInputStream(tcpSocket.getInputStream());
    }
    catch (IOException ex)
    {
        logger.error("Tcp Socket Init Error Error ", ex);
    }

}

public boolean isConnected()
{
    return connected;
}

protected synchronized Object readObject() throws IOException, ClassNotFoundException
{
    Object readObject = null;
    //blocks here
    logger.trace("{} About to block for read Object");

    readObject = this.inputStream.readObject();
    logger.trace("{} Read Object from Stream: {} ", "", readObject);

    return readObject;
}

public void close()
{
    try
    {
        //todo
        this.connected = false;
        this.outputStream.flush();
        this.outputStream.close();
        this.inputStream.close();
        synchronized (tcpSocket)
        {
            this.tcpSocket.close();
        }
    }
    catch (IOException ex)
    {
        logger.error("Error closing Socket");
    }
}

@Override
public void run()
{

    this.connected = true;

    while (this.connected)
    {
        try
        {
            Object readObject = readObject();

            if (readObject != null)
            {
                this.messageProcessor.enqueueReceivedMessage((MessageType) readObject);
            }
            else
            {
                logger.error("Read Object is null");
            }
        }
        catch (IOException ex)
        {
            logger.error("TcpRecieveThread IOException", ex);
        }
        catch (ClassNotFoundException ex)
        {
            logger.error("TcpRecieveThread ClassnotFound", ex);
        }
    }
    this.close();

}
}

Answer 1

1. Profile it. That is likely to tell you a lot.

2. Yes - serializing and deserializing objects using Java ObjectIOStreams is relatively CPU intensive.

3. You don't appear to be using BufferedInputStream / BufferedOutputStream in your IO pipelines, so it is quite possible that data is being read and written one byte at a time. That is likely to increase your CPU usage dramatically.

---

I am saying this thread should be blocked and taking up 0% of cpu when ReadObject is called.

I think you are fundamentally misunderstanding how I/O in general and readObject in particular works. When you call the method, it makes one (or possibly many) system calls to fetch bytes from the socket. Then, it decodes those bytes to figure out what objects need to be created, and then creates and initializes them. All of this work takes CPU time that is accounted to process as "user time" or "system time". The only time when the CPU is not being accounted to the process is when / if a read syscall has to wait for a network packet to arrive.

I also don't believe those "profiling" results. For a start, a straight-forward reading of your code says that the main method creates a new thread, starts it and then immediately returns. Yet those results seem to be saying that the "main" thread is running continuously. That is nonsensical ... and calls into doubt the methodology you are using to do the profiling and/or the way you are interpreting them to us.

---

One more thing to check. Have you looked at the log file? Is the logging is correctly configured?

Answer 2

May be you can look at this way in order to improve it.

1. Try using custom writeObject and readObject()

2. Try Google Protocol Buffers

3. Compressing the stream

4. When you serialize an object, provide serialization only for the required attributes.Do not serialize entire object.So use transient.

Worth looking this discussion: Java Object Serialization Performance tips