2009년 6월, 주키퍼(zookeeper)에서 cpu 튀는 현상이 발생했다는 버그가 리포트되었다.

ZooKeeper server unexpectedly high CPU utilisation
https://issues.apache.org/jira/browse/ZOOKEEPER-427

(현상)

5개 노드의 zookeeper를 돌리는데 cpu가 95%까지 튀는 현상이 발견되었다.

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
6883 infact 22 0 725m 41m 4188 S 95 0.5 5671:54 java

(결론)

다들 jvm을 의심을 했지만. 드라마틱하게 문제는 zookeeper 자체 코드였다.

 

zookeeper의 org/apache/zookeeper/server/quorum/QuorumCnxManager.java 소스의 Thread 클래스를 상속받은 RecvWorker 내부 클래스의 run() 메서드에서 받아야 할 메시지를 처리를 잘 못하면서 cpu가 튀었다.

처음 메시지를 받는 4byte를 읽으려고 하는데, 그냥 읽기만 했지 잘못된 메세지를

 

class RecvWorker extends Thread {

    Long sid;

    SocketChannel channel;

    volatile boolean running = true;

     final SendWorker sw;

 

    RecvWorker(SocketChannel channel, Long sid, SendWorker sw) {

        this.sid = sid;

        this.channel = channel;

        this.sw = sw;

    }

 

    public void run() {

        threadCnt.incrementAndGet();

        try {

        byte[] size = new byte[4];

        ByteBuffer msgLength = ByteBuffer.wrap(size);

        while (running && !shutdown && channel != null) {

            while (msgLength.hasRemaining()) {

-                channel.read(msgLength);  // 기존 코드

+                if (channel.read(msgLength) < 0) { // 수정된 코드

+                      throw new IOException("Channel eof");

+                }

       }

       msgLength.position(0);

      int length = msgLength.getInt();

      if(length <= 0) {

         throw new IOException("Invalid packet length:" + length);

      }

}

 

원인은 다음과 같다.


서버가 동작되고 (running=true,  shutdown=false), 채널은 연결되고 (channel instance not null), 4byte를 읽으려고 하는데, 다른 zookeeper의 인스턴스에서 stop하고 –1 을 리턴할 때 이에 대한 처리가 없었다. (channel.read(msgLength) = 1) 그래서 계속 while 문이 반복되면서 cpu ratio가 95%까지 올라갔다.

 

패치는 channel의 첫 바이트를 읽어 문제가 될 때는 IOException을 던져 개발자가 처리할 수 있게 했다.

 

통신프로그램에서는 (nio이든, io이든) read() 메서드에 대해서는 항상 체크하는 습관이 필요하다.

Posted by '김용환'
,