{"id":"IL-0457","org":"LINE","date":"2019-02-15","docs":[],"title":{"en":"The HA HDFS NameNode of a log-collection Hadoop cluster failed over around 09:00 after its ZKFC health check timed out","ko":"로그 수집 Hadoop 클러스터의 HA HDFS NameNode 가 오전 9시쯤 가끔씩 failover 됐다"},"domain":["database"],"impact":{"scope":"The HA HDFS NameNode of the log-collection Hadoop cluster failed over now and then around 09:00","users":"unknown","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":null,"related":[],"sources":[{"url":"https://engineering.linecorp.com/ko/blog/data-engineering-software-troubleshooting","kind":"blog","archived":"https://web.archive.org/web/20250925135153/https://engineering.linecorp.com/ko/blog/data-engineering-software-troubleshooting"}],"summary":{"en":"The Hadoop cluster, built on HDP-2.6.1.0 (2.6.1.0-129) with HDFS 2.7.3, collects the access and application logs of servers with fluentd and loads them into Apache Hive tables with an hourly ETL batch. fluentd writes log files into an HDFS directory, Hive LOAD DATA moves them into an intermediate table directory, Hive INSERT ... SELECT writes them into the final table in another file format, and Hive ALTER TABLE ... DROP PARTITION deletes the files of the intermediate table, which on this cluster moves them into the .Trash directory. With fs.trash.interval at 4320 minutes, the files under .Trash were deleted every 3 days, and that deletion held the NameNode's FSNamesystem write lock for long periods. RPC calls piled up in the client RPC port queue, and because the ZKFC health check used the same port, it timed out after 60 seconds and caused a failover.\n\nThe team chose two fixes. It changed fs.trash.interval from 4320 to 1440 so the files under .Trash are deleted every day, which shortens the time the deletion holds the write lock. It also set up the Service RPC port, a port used only for the health checks of the ZKFC and the DataNodes (including block reports), with dfs.namenode.servicerpc-address.mycluster.nn1=mynamenode1:8040 and dfs.namenode.servicerpc-address.mycluster.nn2=mynamenode2:8040, so the NameNode can answer the ZKFC health check without delay even when mass file deletion fills the client RPC port queue.","ko":"LINE Data Labs 는 fluentd 로 각 서버의 접속 로그와 애플리케이션 로그를 모으는 Hadoop 클러스터를 운영한다. 클러스터는 HDP-2.6.1.0 이고 HDFS 버전은 2.7.3 이다. 로그 파일은 매시간 ETL 배치로 Hive 테이블에 등록된다. 배치의 마지막 단계에서 ALTER TABLE ... DROP PARTITION 으로 지운 중간 테이블 파일은 .Trash 디렉터리로 옮겨진다. 이 클러스터의 HA 구성 HDFS NameNode 가 오전 9시쯤 가끔씩 failover 됐다.\n\nZooKeeper Failover Controller 로그에는 NameNode 헬스 체크가 60000 millis 타임아웃에 걸린 기록이 남았다. failover 직전 NameNode 로그를 보니 TrashPolicyDefault 가 .Trash 디렉터리를 비우기 시작했고, 디렉터리 하나를 지우면서 FSNamesystem write lock 이 36094 ms 동안 잡혀 있었다. 이어서 블록을 지우는 동안 1~7초의 GC pause 가 나며 write lock 이 계속 잡혔다. 그사이 NameNode RPC Client Port 큐에 처리되지 못한 RPC 호출이 3,500개 정도 쌓였다. ZooKeeper Failover Controller 의 헬스 체크도 같은 포트로 들어가 큐에서 오래 기다리다 타임아웃됐고, 그 결과 failover 가 난 것으로 보였다.\n\n팀은 fs.trash.interval 을 4320 에서 1440 으로 바꿔 .Trash 파일을 3일이 아니라 1일 간격으로 지우게 했다. .Trash 파일을 지울 때 write lock 이 잡히는 시간을 줄이려는 조치였다. 또 dfs.namenode.servicerpc-address 로 Service RPC port 를 따로 설정하기로 했다. Service RPC port 는 ZooKeeper Failover Controller 와 DataNode 의 헬스 체크를 받는 전용 포트다. 이 포트를 쓰면 RPC Client Port 큐에 호출이 쌓여도 NameNode 가 헬스 체크에 지연 없이 응답할 수 있다."},"trigger":{"en":"Around 09:00 the NameNode began deleting the files under the .Trash checkpoint (TrashPolicyDefault#deleteCheckpoint), and deleting one directory held the FSNamesystem write lock for about 36 seconds.","ko":"오전 9시쯤 NameNode 가 .Trash 디렉터리에 쌓인 삭제된 로그 데이터 파일을 지우는 작업을 시작했다. fs.trash.interval 이 4320 분이어서 .Trash 아래 파일은 3일 간격으로 지워지고 있었다."},"severity":"unknown","symptoms":["unnecessary-failover","lock-contention","intermittent-timeouts"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"published","detection":null,"components":["shared-filesystem","failover-manager"],"root_cause":"capacity","remediation":[{"text":{"en":"Changed fs.trash.interval from 4320 to 1440 so files under .Trash are deleted daily instead of every 3 days","ko":"fs.trash.interval 을 4320 에서 1440 으로 바꿔 .Trash 디렉터리 아래 파일을 3일이 아니라 1일 간격으로 지우게 했다. .Trash 파일을 지울 때 FSNamesystem write lock 이 잡히는 시간을 줄이려는 조치였다."}},{"text":{"en":"Configured a dedicated Service RPC port for the ZKFC and DataNode health checks","ko":"dfs.namenode.servicerpc-address.mycluster.nn1=mynamenode1:8040 과 dfs.namenode.servicerpc-address.mycluster.nn2=mynamenode2:8040 을 추가해 ZooKeeper Failover Controller 의 헬스 체크가 RPC Client Port 대신 Service RPC port 를 쓰게 했다."}}],"action_items":[],"contributing":["default-config-unchanged"],"recurrence_of":null,"symptoms_text":{"en":"The NameNode of an HA HDFS cluster run by LINE Data Labs occasionally failed over at a particular time of day, around 09:00. At the failover the ZooKeeper Failover Controller (ZKFC) logged that its NameNode health check had timed out after 60 seconds: WARN ha.HealthMonitor (HealthMonitor.java:doHealthChecks(211)) - Transport-level exception trying to monitor health of NameNode at xxxx/xxx.xxx.xxx.xxx:xxxx: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read.\n\nThe NameNode log just before the failover showed that, at 09:00:30, the deletion of files under the .Trash directory had started with TrashPolicyDefault#deleteCheckpoint for trashRoot: hdfs://xxxx/user/hive/.Trash. Deleting one directory then held the lock for about 36 seconds, logged as FSNamesystem write lock held for 36094 ms via ... FSNamesystem.delete. More entries followed in which deleting blocks caused GC pauses of 1 to 7 seconds that kept the write lock held, such as Detected pause in JVM or host machine (eg GC): pause of approximately 1487ms and FSNamesystem write lock held for 2038 ms via ... FSNamesystem.removeBlocks.\n\nWhile the write lock was held, about 3,500 unprocessed RPC calls sat in the queue of the NameNode RPC Client Port. The ZKFC log showed that its health check requests went to the same port as that queue, so the health check waited in the queue until it timed out and the ZKFC failed the NameNode over.","ko":"LINE Data Labs 의 로그 수집 Hadoop 클러스터에서 HA 구성의 HDFS NameNode 가 오전 9시쯤 가끔씩 failover 됐다. failover 의 직접 원인은 ZooKeeper Failover Controller 의 NameNode 헬스 체크가 60초 타임아웃에 걸린 것으로 보였다.\n\nfailover 때 ZooKeeper Failover Controller 로그에는 아래 경고가 남았다.\n09:03:08,165 WARN ha.HealthMonitor (HealthMonitor.java:doHealthChecks(211)) - Transport-level exception trying to monitor health of NameNode at xxxx/xxx.xxx.xxx.xxx:xxxx: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read.\n\nfailover 직전 NameNode 로그를 보면 09:00:30 에 .Trash 디렉터리를 비우는 작업이 시작됐다. 디렉터리 하나를 지우는 동안 FSNamesystem write lock 이 약 36초 동안 잡혀 있었다.\n09:00:30,574 INFO fs.TrashPolicyDefault (TrashPolicyDefault.java:deleteCheckpoint(319)) - TrashPolicyDefault#deleteCheckpoint for trashRoot: hdfs://xxxx/user/hive/.Trash\n09:01:06,673 INFO namenode.FSNamesystem (FSNamesystem.java:writeUnlock(1659)) - FSNamesystem write lock held for 36094 ms via\n\n그 뒤에도 블록을 지우는 동안 1~7초짜리 GC pause 가 나면서 write lock 이 계속 잡혔다.\n09:01:17,955 INFO util.JvmPauseMonitor (JvmPauseMonitor.java:run(196)) - Detected pause in JVM or host machine (eg GC): pause of approximately 1487ms\n\n이때 NameNode RPC Client Port 의 큐에는 처리되지 못한 RPC 호출이 3,500개 정도 쌓여 있었다. ZooKeeper Failover Controller 도 헬스 체크를 이 RPC Client Port 로 보내고 있었기 때문에, 헬스 체크 요청 역시 큐에서 오래 기다리다 타임아웃됐다."},"updated_at":"2026-11-14T12:34:10.616367Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0457","org_slug":"line"}