대용량 파일 다운로드 out of memory

대용량 파일을 제공하는 서비스를 운영하다가 문제가 발생했다.
브라우저에서 운영서버로부터 1gb 정도 크기의 zip파일을 다운받으려고 하면 에러가 발생했는데, 로컬환경에서는 이러한 문제가 발생하지 않았다.

운영서버는 도커를 사용해 배포하고 있었고, 로컬 개발환경은 데이터베이스만 도커를 사용하고 애플리케이션은 인텔리제이에서 실행시켰다.

---

서버에서 에러로그를 확인했는데, response 객체에 파일 stream을 쓰는도중 에러가 발생했다.
runcatching 으로 실행하고 발생하는 에러를 커스텀로그 로 찍고있었다. (여기서부터 문제)

• 다운로드가 오래걸려서 timeout 이 발생하나?
• 디스크 용량이 부족한가?
• 파일이 크니까 메모리가 부족한가?

정도의 예상되는 문제점들이 있었고, oom은 관련로그가 당연히 찍힐거라 생각하고 가능성을 지웠다. 특히, 컨테이너에 할당한 메모리가 8gb였기 때문에 더욱 oom의 가능성은 없을거라 확신했다.

---

타임아웃?

테스트 중 524 timeout 에러를 확인했고 리버스 프록시 역할을 하고있는 클라우드 플레어 터널을 통하지 않고 요청을 받게 수정했다.

그 결과 524 에러는 발생하지 않았지만 여전히 response의 output stream을 copy하는 과정에서 에러가 발생했다.

---

디스크 용량부족?

로컬환경에 비해 운영환경에서 크게 제한되는것은 할당되는 자원이다. 디스크, 메모리, cpu 등 여러 자원들이 있지만 cpu와 메모리는 정말 여유롭게 할당했기때문에 디스크 자원이 부족한지 의심했다.

로컬에서는 문제가 발생하지않아 운영환경과 동일하게 구성한 서버에서 테스트하던 중

java.io.IOException: No space left on devic

에러가 발생했고 예외발생 시 일부 파일들이 삭제되지않고 컨테이너에 남이있는것을 확인했다. 예외상황에도 파일이 정상적으로 삭제되게 수정했고, 디스크 공간이 부족한 컨테이너를 재실행시켜 불필요한 파일들을 삭제했다.

---

메모리 부족?

위 2가지 문제를 확인했음에도 여전히 해결되지않아 막막했다. 처음으로 돌아가, 에러가 발생한 부분을 더 자세히 살펴봤다.
문득 커스텀로깅 부분이 눈에 들어왔는데,

response.apply {
            contentType = "application/zip"
            setHeader("Content-Disposition", "attachment; filename=${zip.filename}")
        }

        runCatching {
            zip.inputStream.use { input ->
                response.outputStream.use { output ->
                    input.run {
                        copyTo(output)
                    }
                }
            }
        }.onFailure {
            FileUtils.forceDelete(zip.file)
            throw CustomException(DownloadException.FileStreamCopyFail)
        }.also {
            response.flushBuffer()
            FileUtils.forceDelete(zip.file)
        }

위 코드에서 DownloadException.FileStreamCopyFail 예외를 던지고, 커스텀 예외를 처리하는 global exception handler에서 로깅 및 ResponseEntity 반환을 하고있다.
onFailure에서 받는 throwable 객체를 사용해 로깅하지 않기때문에 직접 정의한 에러만 로깅되고 실제 에러스텍은 로깅되지 않는다.

발생하는 예외를 로깅하는 코드를 추가하고 다시 테스트해봤는데, out of memory 에러가 발생했다.

드디어 문제를 찾았다는 안도감과 함께 어떻게 oom이 발생하지? 하는 의문역시 생겼다. 컨테이너에 할당한 메모리가 8GB인데, 1GB 파일을 다운받을수가 없다? 납득되지않았다.

컨테이너의 리소스 사용량을 다시한번 확인해봤다.

처음 확인했을때는 7.67GB 가 잘 할당되어있구나! 라고 생각했는데, 다시보니 메모리 사용량이 이상했다. oom이 발생해 메모리는 부족한데 메모리를 2GB밖에 사용하지 않고있었다.

'힙메모리를 직접 크게 설정해줘야하나? 별도의 설정이 없으면 호스트의 메모리를 잘 사용해야하지 않나?'
하는 생각이 들었고 알아보니 jvm의 기본 힙메모리 크기는 2GB였다. jar 파일을 실행시킬때 옵션을 줘서 힙 사이즈를 설정할 수 있었다.

CMD ["java", "-XX:MinRAMPercentage=50", "-XX:MaxRAMPercentage=80", "-jar","/usr/src/app/app.jar"]

위 옵션으로 할당된 메모리의 50% ~ 80% 로 힙메모리 크기를 정의했다.
그리고 힙 크기를 확인했는데

예상대로면 최소 3.8GB 정도의 힙메모리가 할당되어야하는데 2GB로 나왔다.
조금 더 알아보니 -XX:+PrintFlagsFinal는 JVM의 기본 설정값을 보여주는 옵션이었다. 실행중인 JVM 인스턴스의 설정을 보기위해서 -XshowSettings:vm 옵션을 사용해야했다.

CMD ["java", "-XX:MinRAMPercentage=50", "-XX:MaxRAMPercentage=80", "-XshowSettings:vm", "-jar","/usr/src/app/app.jar", "-version"]

즉, 출력되는 내용과 상관없이 힙메모리 자체는 정상적으로 할당되었던것이다.

설정대로 힙메모리가 정상적으로 할당되었고, 파일 다운로드 api 역시 정상적으로 동작했다.

---

이번 장애에서 기본적인 로깅을 소홀히 하고, 커스텀 메시지에만 초점을 맞췄던것이 실책이었다. 그리고 JVM에 대해 이해가 부족했던 점이 명확하게 드러났다. 기본에 대한 중요성을 다시 한번 깨닫게 되었다.