Search code examples
javasocketstcpnio

Unexpected behavior of tcp server: why adding delay increases ability to service clients?


Good day everybody!

My question is about NIO based server and my situation is the following: server reads messages from 100 clients (100 client threads) which send 100 messages each. So, total number of messages is 100x100 = 10000. I have incoming messages counter in my server which increases after reading some message from some client. When I just read message my server reads approximately 9200 messages. When I add dummy loop for simulationg service delay my server surprisingly services all 10000 messages!

My expectations are something like this - OK, server manages to read all 10000 messages even with short delay. So, without this delay server probably can read more messages (service more clients). But you see, this is wrong. Without delay things getting worse. Here I described my architechture. The only modification in my current logic is dividing accepting clients and reading messages into 2 different threads: one selector accepts clients in one thread, second selector waits messages from connected clients in other thread.

Client code

public class TCPClient implements Runnable{

private String name;
private static TCPClient[] clients;
private static Thread[] threads;
private int counter = 0;

public TCPClient(String name)
{
  this.name = name;
  this.counter = 0;
}

public static void main(String[] args) throws Exception
{
   clients = new TCPClient[100];
   threads = new Thread[100];
   for(int i=0;i<100;i++) 
   {
       clients[i] = new TCPClient("thread # "+Integer.toString(i));
       threads[i] = new Thread(clients[i]);
       threads[i].start(); 
       // Thread.sleep(500);
   }
   for(int i=0;i<100;i++) 
   {
       threads[i].join();
   }
   for(int i=0;i<100;i++){
       System.out.println("counter = "+clients[i].counter);
   }

}

@Override
public void run()
{
   Socket socket = null;
   OutputStream out = null;

   try
   {
        socket = new Socket();
        socket.connect(new InetSocketAddress("192.168.3.109",2345), 0); 
        out =  socket.getOutputStream();

        byte[] bytes;
        while(counter < 100)
        {
            counter++;
            bytes = (name+ ", message # "+Integer.toString(counter)+System.lineSeparator()).getBytes();
           // System.out.println(counter);
            out.write(bytes); 
            out.flush();
            Thread.sleep(200);
        }
   }
   catch(Exception ex)
   {
            System.out.println(name+" "+Integer.toString(counter));
            ex.printStackTrace(new PrintStream(System.out));
            System.out.println();
   }
    finally
    { 
        if(socket!=null && out!=null)
        {
            try
            {
                socket.close();
                out.close();
            }
            catch(Exception ex)
            {
                System.out.println("client close error");
            }
        }
    }
}

}

Server code (message reading part)

@Override
public void run() 
{
    isRunning = true;
    int acc = 0;
    boolean error = false;
    while (isRunning) {
      try 
      {


             selector.select(); 

             Set keys =  selector.selectedKeys();
             Iterator it = keys.iterator(); 
             while(it.hasNext())
             {
                 SelectionKey key = (SelectionKey)it.next();



                 if (key.isReadable())
                 { 
                       //readMessage(key);
                       //key.cancel();

                      // ByteBuffer bbb =  ByteBuffer.allocate(2048);
                      // key.cancel();
                       curTime = System.currentTimeMillis();
                       SocketChannel sc = (SocketChannel) key.channel();
                       // System.out.println("before reading"); 
                       bb.clear();
                       int x =  sc.read(bb); 

                       if(x==-1)
                       {
                           key.cancel();
                           //System.out.println("cancelling key");
                           continue;
                       }

                       counter++;
                      // bb.flip();
                       //System.out.print(decoder.decode(bb).toString());
                     //  Thread.sleep(20);
                       long sum=0;
                       for(int dummy=0;dummy<250000;dummy++)
                       {
                           sum += dummy;
                         //  sum %= 1005;
                       }
                       long delta  = System.currentTimeMillis() - curTime;
                       serviceTime += delta;

                       if(counter>9000)
                       {
                           System.out.println("recieved messages count = "+counter);
                           System.out.println("one message  service time = "+delta+" milliseconds");
                           System.out.println("total service time = "+serviceTime+" milliseconds");
                           System.out.println("sum = "+sum); //11 249 925 000
                       }

                     // selector.wakeup();
                      //key.interestOps(SelectionKey.OP_READ); 


                 } 
             }

             keys.clear();





      } 
      catch (Exception ex) 
      {     
          error = true;  
          System.out.println("error in recieving messages "+ex.getMessage());
          ex.printStackTrace(new PrintStream(System.out));
         // logger.println("error in recieving messages "+ex.getMessage());
         // logger.flush();
      }
      finally
      {
            //if(error) // !!!!!!!!!!! DO NOT STOP THE SERVER EDIT IT LATER
            //stopServer();
      }
    }
}

Probably useful information - delay between each 2 messages on client side is 200 milliseconds. When dummy loop makes 200000-220000 iterations server works perfectly. BTW, 200000 iterations is approximately 200 ms - beacause number of clients is 100, so delay in one select() is 100*200000 = 2 million iterations - 200 ms for modern PC. If dummy loop makes less than 200000 iterations server reads ~9200 messages. What is the reason of such strange behavior?


Solution

  • There are so many problems here it is difficult to know where to start.

    1. When read() returns -1 you must close the channel. Cancelling the key is not sufficent: you have just leaked a socket.

    2. If read() returns a positive integer, it is a read count, which you are ignoring. You are assuming you got an entire message.

    3. If you get any IOException doing I/O on a Channel you must close the channel.

    Probably you aren't receiving entire message unless you put the sleeps in. Or else when you put the sleeps in you get more than one message at a time, so you process faster.

    Adding the sleeps just fixes your bugs, it doesn't have magical properties of its own.