Airflow와 야근하기

지난 주에 쓸데없이 야근한 일이 있어 이를 기록해두고자 합니다.

재발 방지를 위하여.

평화로운 9월 7일 오후

9월 5일에 스파르톤을 마치고 컨디션이 화요일까지 영 회복이 되지 않았습니다. 월요일에도 왜인지 잠을 제대로 이루지 못해서 화요일 컨디션이 좋지 않았습니다. 빠르게 할 일 하고 칼퇴해야겠다는 결심을 하고, 출근을 했습니다. 당일에 계획된 작업은 ECS TASK로 변경한 airflow의 워커 상태와 main server, metaDB를 점검하고, airflow의 스케쥴러를 안정화 하기 위해서 웹서버와 스케쥴러를 데몬 서비스로 등록하는 것이었습니다. 그동안 서비스로 등록하는 것에 대해서 망설였었는데, 공식 문서에도 서비스 등록에 대한 내용이 있기도 했고, 파이썬 코드를 통해서 상태를 점검하는 것보다 더 안정적일 것이라는 생각에 서비스로 등록하기로 했습니다. 서비스로 등록하는 것에 대해서는 airflow 공식 github에 있는 파일을 사용하면 됩니다.

서비스로 등록해서 사용하는 글은 생각보다 굉장히 많았습니다. 쿠버네티스를 활용해서 스케쥴러를 돌보는게 요즘 트렌드긴 하지만, 쿠버네티스를 사용할 정도가 아닌 조직같은 경우에는 서비스로 등록해서 많이 사용하는 것 같았습니다. 어쨌든 이 파일을 이용해서 서비스 파일을 만들었고 서비스에 필요한 요소들, 예를 들어 Unit, Service, Install에 대해서 다시 한번 살펴봤습니다. 각 항목에 대한 내용들을 작성하고 환경에 맞게 튜닝을 조금 했습니다. 그리고 여러번 적용하고 다시 등록하고… 결국 서비스가 등록되고 start된 것이 확인 되었습니다. 하지만, 조금 이상했던 것은 main 서버의 CPU이용률이 이전보다 증가했다는 것입니다. CPU이용률이 벌써부터 올라가면 별로 좋지 않을 것 같아서 CPU이용률을 줄여보기 위해 airflow.cfg를 조금 수정해주기로 했습니다. 예전에 살펴봤던 글에 CPU이용률을 낮추는 설정이 기억나서 이를 적용해보기로 했습니다. scheduler_heartbeat_sec = 60, min_file_process_interval =60, max_threads = 1 로 설정을 변경하는 것이 주 내용이었습니다. scheduler_heartbeat_sec은 스케줄러가 새로운 작업을 실행해야 하는 빈도 (초)를 정의하는 설정입니다. 이 시간을 적게 설정한다면, 더 자주 스케쥴러를 실행시키기 때문에 CPU의 이용률이 높아질 수 밖에 없습니다. min_file_process_interval은 DAG 업데이트 시간을 조정하는 값입니다. 스케쥴러와는 큰 관계가 없지만 웹서버의 부하를 일으킬 수 있기때문에 CPU와 연관이 있습니다. 이 두 값을 조정하고 적용했습니다. CPU가 조금 내려갔습니다. 서비스도 문제가 없었습니다.

문제의 발생

서비스가 성공적으로 등록되어서, 서비스 등록에 대해서 팀원들에게 공유하는 시간을 가졌습니다. 여러저러 설명을 하고 airflow의 스케쥴러의 상태를 확인을 했습니다. airflow주소:8080/health 면 간단하게 메타DB와 스케쥴러의 상태를 확인할 수 있습니다. 그런데 여기에 unhealthy 라고 나오기 시작했습니다. 더 이상한 것은, unhealthy하다면 last_heartbeat_time은 죽은 이후부터 업데이트가 되면 안되는데, 계속해서 업데이트가 되고 있었습니다. 심신이 매우 피곤했던 상황이었기 때문에 멘탈이 깨지기 시작했습니다. 가뜩이나 ECS워커로 변경한 뒤에 문제가 없나 노심초사하고 있었는데, ECS워커의 설정이 뭐가 잘못된 것인지, 서비스에 이상이 있는 건지 감이 잘 잡히지 않았습니다. 정신없던 와중에 퇴근시간이 지났습니다.

야근의 시작

본격적으로 초과근무를 하기 시작했습니다. 금방 끝날 것이라고 생각해서 서비스를 중단하고 웹서버와 스케쥴러를 다시 시작하면 해결이 될 것이라고 생각했습니다. 몇 번을 죽이고 살리고를 반복했지만 별 효과가 없었습니다. airflow가 사람을 놀리기라도 하는듯이 다시 시작하고 처음 몇 초간은 healthy 라고 나오다가 ‘휴 끝났네… 한번만 더 확인해볼까?’ 하는 순간 unhealthy로 나왔습니다. 정신이 혼미해져가는 와중에 ‘새로 airflow서버를 띄우면 고생하긴 하겠지만 되겠지’란 생각에 메인 서버 하나를 종료하고 미리 저장된 AMI를 이용해서 새 서버를 올렸습니다.

새로 서버를 올렸더니, 아주 잘 되기 시작합니다.

‘휴 해치웠나…?’

클리셰는 역시 클리셰였습니다. airflow를 사용하는 것이 두 영역인데, 한 영역은 잘 되었지만, 다른 영역은 비웃기라도 하듯 잘 되지 않는 것이 아니겠습니까. 무엇이 문제일까 다시 고민하기 시작했습니다. 하지만 크게 문제될 부분도 없었고 ECS워커부분의 로그도 너무 조용했습니다. 그러다가 로그에 작업이 실행되는 것이 발견되어서, ‘스케쥴러가 죽어있는데 작업이 어떻게 돌지?’ 란 생각에 한 DAG를 수동으로 돌렸습니다. 놀랍게도 느리긴 했지만 작업이 실행되었습니다. 작업은 DAG를 파싱하고, 스케쥴링이 된 상태에서, 큐를 내주고, 워커에서 해당 큐를 가져가서 코드에 적힌대로 수행하게 되어있습니다. 그렇다면 스케쥴러는 unhealthy하긴 하지만, 실제로는 죽어있는 것이 아닌 것이 됩니다.

여러 커뮤니티에 도움을 청해놔서 그 분들의 의견을 확인해 봤습니다. “스케쥴러가 때로는 실제로 돌아가고 있는데 webserver에서 이를 못 잡을 수도 있으니 다시 완벽하게 kill하고 다시 실행해 봐라” 라는 의견의 주였습니다. 또 다시 스케쥴러를 내리고 올리고를 반복했습니다. 하지만 해결이 되지 않았습니다. 할 수 있는 건 정말 다 해봤는데, 그래서 희대의 뻘짓인 airflow reset db 까지 하게 됩니다. 이 명령어를 metaDB에 있는 모든 데이터를 날리는 일입니다. 제가 설정해둔 variables와 connections의 값을 다 날리는 것입니다. 물론 값을 백업해두고 한 일이라 복구하는데 어렵지는 않았지만, 이렇게 해결해서는 안된다고… 생각합니다.

또 다시 airflow를 종료하고 새롭게 airflow를 올렸는데, 이번에는 ECS에서 이상한 로그를 하나가 발견되기 시작합니다. Cannot connect to .... redis.... 레디스에 연결이 안된다는 것입니다. 그래서 main서버에 접속해서 redis-server의 프로세스를 확인해 봤더니, 프로세스가 정말 없었습니다. 왜 레디스가 죽었지? 하다가 데몬 서비스로 등록한 파일이 생각났습니다. 그 파일의 Unit부분에 After와 Wants에는 redis.service 부분이 있었는데, 서비스가 실행될때 레디스를 건드린 것 같았습니다. 레디스를 복구하고 다시 작업을 확인해보니, 이제는 작업은 실행되지만, 여전히 unhealthy한 스케쥴러가 남아있는 것이 확인되었습니다. 그러다가 오전에 CPU 이용률 때문에 설정한 scheduler_heartbeat_sec가 생각났습니다.

오전에 설정할 때 60초는 너무 긴 것 같아 40초로 설정을 했습니다. 그리고 설정 값을 쭉 보다가 scheduler_health_check_threshold라는 것도 한번 봤습니다. 기본 값이 30초였는데, 관련 없는 값이라고 생각되어 그냥 넘어갔었습니다. 하지만, 이게 바로 이 야근을 한 원인이었다는 것을 12시가 다되어서야 발견을 하게 되었습니다.

If the last scheduler heartbeat happened more than scheduler_health_check_threshold
ago (in seconds), scheduler is considered unhealthy.
This is used by the health check in the "/health" endpoint

설정에는 이렇게 설명되어 있습니다. last scheduler heartbeat가 scheduler_health_check_threshold보다 더 자주 발생하면, unhealthy라고 나올 것이라고, 그리고 이 정보는 /health 에 사용된다고…

그러니까 정리하자면, 오전에 CPU이용률을 줄이려고 scheduler_heartbeat_sec을 40초로 설정을 했는데, 이 값보다 scheduler_health_check_threshold가 더 적은 값인 30이게 되어서 health 체크를 하는 시간 보다 sheduler_hearbeat_sec가 더 자주 발생하게 되어서 unhealthy하다고 /health에서 표시가 된 것이었습니다. 스케쥴러는 사실상 프로세스가 떠 있고 작업을 하고 있으니 문제는 없었던 것이 맞았습니다.

그러니까… 쓸데없이 airflow를 처음부터 다시 띄우고… metaDB를 rest할 필요도 없었고, 야근할 필요도 없었던 거시었슴미다.

피곤이 몰려오기 시작했습니다.

Outro

9월 8일 00:20분 경에는 비가 왔습니다. 택시를 콜하니 대어를 물기 위해 5초만에 기사님이 잡혔습니다. 풀이 죽은 야간 추가 근무자와는 반대로 택시기사님은 격양되어 있는 것 같았습니다. 조용히 이어폰을 꽂았고 재밌어보이는 유튜브 영상을 보면서, 무슨 내용인지도 기억이 안나지만, 그렇게 집으로 왔습니다.

29,600원짜리 교훈이었습니다.

설정값을 제대로 확인을 하지 않고, 수면 부족의 콜라보로 이루어낸 결과였습니다. airflow가 또 터지는 악몽을 꿨고, 다음날 겨우 지각을 면하면서 아슬아슬하게 출근을 했습니다.

잠은 평소에 잘 자야하는 것 같습니다.