들어가며

LINE Plus의 MPR(Mobile Productive & Research) 팀은 LINE 클라이언트 앱의 빌드 개선과 CI 파이프라인 관리, 자동화 지원 등의 업무를 담당하고 있습니다. 이번 글에서는 저희 팀에서 운영하는 CI/CD에 발생했던 흔하지 않은 이슈와 그 해결 방법을 공유하려고 합니다. 이번 글에서 다룰 이슈는 문제가 발생한 시점부터 다시 정상적으로 CI/CD가 운영되기까지 약 10일 정도의 시간이 소요됐는데요. 추후 유사한 문제가 발생했을 때 어떤 식으로 문제의 원인을 찾고, 분석해서, 해결해 나가야 하는지 그 과정을 참고하고자 작성했습니다. 저희의 문제 해결 과정이 이 글을 읽고 계신 분들께도 도움이 되기를 바라며 시작하겠습니다.

현재 MPR 팀에서 운영하고 있는 CI의 전체 구성을 간략하게 소개하겠습니다. 먼저 소스 리포지터리로 Git을 사용하고 있으며, Jenkins와 여러 플러그인을 이용해 CI를 운영하고 있습니다. 빌드 개선 및 오류 검토를 목적으로 Gradle을 활용한 빌드 정보를 Develocity에 수집하고 있으며, Jenkins 빌드 로그를 Logstash를 통해 Elasticsearch로 모아서 집계한 뒤 Kibana 및 Grafana를 사용해 빌드 정보를 시각화하고 있습니다.

각 도구 소개

Gradle
- Java나 Kotlin, Groovy, Scala 등 다양한 언어로 작성된 프로젝트를 위한 오픈소스 빌드 자동화 도구로, 주로 소프트웨어 프로젝트의 빌드, 테스트, 배포를 자동화하는 데 사용합니다.
Develocity
- Gradle의 기능을 확장해 빌드 성능 최적화, 문제 진단, 협업 관련 기능 등을 제공하는 상업용 솔루션입니다.
- 특징
  - 빌드 스캔(Build Scan): 빌드 및 테스트 실행에 대한 상세한 데이터를 수집하고 분석하여 성능 병목 현상이나 실패 원인을 파악할 수 있습니다.
  - 캐시 성능 최적화: 빌드 캐시를 활용하여 빌드 시간을 단축하고 효율성을 높입니다.
  - 분석 및 진단: 빌드 및 테스트의 성능을 분석하고 문제를 진단하는 데 도움을 줍니다.
  - 협업 기능: 팀 내에서 빌드 데이터를 공유하고 협업할 수 있는 기능을 제공합니다.
Elasticsearch
- 대량의 데이터를 실시간으로 저장, 검색, 분석할 수 있는 분산 검색 및 분석 엔진입니다.
- 특징: JSON 형식의 문서로 데이터를 저장하며, 검색 기능이 강력하고 확장성 및 고가용성이 뛰어납니다.
Logstash
- 데이터 수집 및 처리 파이프라인 도구입니다. 다양한 소스에서 데이터를 수집해서 변환 및 필터링한 후 Elasticsearch로 전송합니다.
- 특징: 플러그인 아키텍처를 통해 다양한 입력, 필터, 출력 옵션을 지원합니다.
Kibana
- 데이터 시각화 도구로, Elasticsearch에 저장된 데이터를 기반으로 대시보드를 구성해 데이터를 시각화할 수 있습니다.
- 특징: 사용자 친화적인 인터페이스를 갖추고 있으며, 대화형 차트 및 그래프 작성 기능과 실시간 데이터 모니터링 기능을 지원합니다.
Grafana
- 오픈 소스 데이터 시각화 및 모니터링 도구로, 다양한 데이터 소스에서 데이터를 수집하여 대시보드 형태로 시각화할 수 있습니다.
- 특징
  - 다양한 데이터 소스 지원
    - Grafana는 Prometheus, InfluxDB, Graphite, Elasticsearch, MySQL, PostgreSQL 등 다양한 데이터 소스와 통합할 수 있습니다.
    - 플러그인 아키텍처를 이용해 쉽게 데이터 소스를 추가할 수 있습니다.
  - 대시보드를 통한 데이터 시각화
    - 사용자 정의 대시보드를 생성해 다양한 차트와 그래프, 테이블로 데이터를 시각화할 수 있습니다.
    - 실시간 데이터 스트리밍을 지원해 최신 데이터를 즉시 반영할 수 있습니다.
  - 경고 및 알림 기능
    - 특정 조건이 충족되면 경고를 보내도록 설정할 수 있고, 이메일이나 Slack, PagerDuty 등 다양한 채널로 알림을 보낼 수 있습니다.
    - 경고 규칙을 이용해 시스템 상태를 지속적으로 모니터링할 수 있습니다.
  - 사용자 관리 및 권한 설정 기능
    - LDAP 및 OAuth를 통한 인증을 지원합니다.
    - 사용자 혹은 팀 기반의 접근 제어를 통해 대시보드와 데이터 소스 접근 권한을 관리할 수 있습니다.
  - 플러그인을 통한 확장
    - 다양한 플러그인을 통해 기능을 확장할 수 있으며, 커뮤니티에서 제공하는 플러그인을 활용할 수 있습니다.
    - 사용자 정의 패널 및 데이터 소스 플러그인을 개발할 수 있습니다.
Jenkins
- 소프트웨어 개발의 CI 서비스를 제공하는 툴입니다. 다양한 플러그인을 통해 소프트웨어 개발의 모든 단계에서 자동화를 지원합니다.
- 특징
  - 플러그인 기반 아키텍처
    - Jenkins는 1,000개 이상의 플러그인을 제공하며, 이를 이용해 빌드와 배포, 자동화 작업을 확장할 수 있습니다.
    - 다양한 버전 관리 시스템(Git, SVN 등)과 빌드 도구(Maven, Gradle 등) 및 테스트 프레임워크와 통합할 수 있습니다.
  - 확장성과 커스터마이징
    - 스크립트 및 파이프라인 DSL(Domain Specific Language)을 사용해 복잡한 빌드 및 배포 프로세스를 정의할 수 있습니다.
    - 다양한 커스터마이징 옵션을 이용해 특정 요구 사항에 맞게 Jenkins를 조정할 수 있습니다.

평소와는 다른 빌드 실패 증상의 발현

언제부터인가 빌드 실패 알림이 증가했습니다. CI/CD를 운영하다 보면 예기치 못한 여러 문제가 발생할 수 있으며, 그중 빌드 오류가 발생하는 경우는 다음과 같습니다.

테스트 관련 오류
- 플레이키(flaky) 테스트: 코드는 동일한데 테스트 결과는 다른 경우
- 느린 테스트: 테스트 실행하는 데 지나치게 오래 걸리는 경우
인프라 및 성능 관련 오류
- 서버 과부하: 동시에 여러 테스트를 처리하느라 서버나 네트워크에 과부하가 걸리는 경우
- 확장성 문제: 개발 팀과 프로젝트의 규모가 커지면서 파이프라인이 증가된 부하를 처리하지 못하지만 구조상 확장하기 어려운 경우
- 성능 이상: 서버의 응답이 지연되거나 메모리 누수가 발생하거나 부하 분산이 적절히 처리되지 않은 경우
통합 및 배포 관련 오류
- 도구 간 통합 문제: 내부적으로 인터페이스를 구축해 서로 다른 도구를 통합해서 사용하다가 예상치 못한 도구 간 설정 호환 문제가 발생하는 경우

일반적인 경우 빌드 실패의 주요 원인은 유닛 테스트 증가에 따른 빌드 및 테스트 수행 시간의 증가입니다. Jenkins에 빌드 타임아웃 시간을 설정해 놓으면 빌드 및 테스트하는 데 이보다 시간이 오래 걸릴 경우 강제로 중단되는데요. 유닛 테스트가 늘어나 테스트 수행 시간이 증가하거나 일시적으로 자원이 부족해 테스트 수행에 실패하면서 설정해 놓은 빌드 타임아웃 시간을 초과하면 빌드에 실패합니다. 보통 이런 경우는 빌드에 사용할 리소스가 일시적으로 부족하거나 네트워크에 간헐적으로 문제가 생겨 발생하기 때문에 빌드를 다시 실행하면 대부분 재현되지 않습니다.

저희는 이번 경우 역시 처음에는 이처럼 시간이 지나면 자연스럽게 해결될 일시적인 증상으로 간주하고 원인을 파악하기 시작했습니다. 그런데 평소와 다르게 여러 시도에도 불구하고 원인을 파악하지 못했고, 오히려 발생 빈도가 점점 늘어나면서 개발 전반에 영향을 끼치기 시작했습니다. 빌드를 다시 실행해도 문제는 해결되지 않았고, 타임아웃 값을 두 배 이상 늘려도 여전히 시간 내에 빌드가 완료되지 않아 빌드 실패로 판단되는 시점만 미뤄질 뿐이었습니다. 그러면서 상황은 점차 악화돼 어느새 업무 시간에 CI에서 수행되는 특정 빌드의 80% 정도가 실패하고 있었습니다. 업무 시간 종료 후에도 실패 비율이 떨어질 뿐 동일한 이유로 실패하는 빌드가 계속 나오고 있었습니다.

빌드 실패 원인 탐색

저희는 이 문제가 쉽게 해결할 수 없는 문제라고 판단하고 며칠간 모니터링하면서 실패한 빌드에서 다음과 같은 공통점을 발견했습니다.

Jenkins에서는 테스트 수행 중 발생한 타임아웃으로 실패로 인지함
로컬 빌드에서는 발생하지 않음
빌드가 많이 몰리지 않는 시간에는 실패 빈도가 줄어듦

이 공통점을 염두에 둔 채 다시 로그를 천천히 살펴보기 시작했습니다.

Gradle 데몬 종료 메시지 발견

로그를 살펴보면서 Gradle 데몬(daemon)이 종료됐다는 메시지를 발견했습니다.

----- Last  20 lines from daemon log file - daemon-71697.out.log -----
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
 
~ snip ~
 
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
[DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
----- End of the daemon log -----
 
FAILURE: Build failed with an exception.
 
* What went wrong:
Gradle build daemon disappeared unexpectedly (it may have been killed or may have crashed)

이에 Gradle 데몬이 종료된 이유를 찾고자 Gradle 플러그인과 Develocity을 포함한 Gradle 관련 도구의 변경 사항을 모두 확인했으나 특별한 문제를 찾지는 못했습니다. Develocity로 빌드 로그를 전송하는 부분에서 문제가 발생한 것은 아닌지 확인해 보기 위해 Gradle 실행 시 --no-scan 옵션을 설정해 빌드 정보를 보내지 않도록 설정도 해 봤지만 문제는 해결되지 않았습니다.

메모리 문제?

실제 테스트를 수행하는 CI 슬레이브 머신에서 OOM(out of memory)가 발생해 Gradle 데몬을 종료시켰을 수도 있다고 생각해 실제 잡을 수행했던 슬레이브의 시스템 로그를 확인해 봤지만 OOM 관련 메시지는 찾지 못했습니다. 메모리 할당량을 늘려보기도 했습니다. LINE Android 프로젝트의 빌드 시스템은 Gradle 프로퍼티를 이용해 빌드 환경에 따라 적절하게 시스템 자원을 할당할 수 있도록 구성돼 있는데요. Gradle 프로퍼티를 이용해 테스트 익스큐터(executor) 개수와 메모리 할당량을 다음과 같이 조정해 봤지만 문제는 해결되지 않았습니다.

익스큐터 개수: 40개 → 30개
힙 메모리: 6G → 8G

타임스탬프 차이 발견

문제를 해결하기 위해 로그를 조금 더 자세히 확인하다가 다음과 같은 두 가지 이상 증상을 확인했습니다.

Jenkins 콘솔에서 타임아웃이 발생한 빌드에 대한 정보를 Develocity의 로그에서 발견했는데 해당 로그에서는 Gradle의 빌드가 정상 완료로 표시돼 있음
Develocity에 수집돼 있는 Gradle의 빌드 정보와 Jenkins 콘솔에서 확인한 로그의 타임스탬프 값이 다름

Jenkins 로그

16:01:44 Starting a Gradle Daemon (subsequent builds will be faster)
16:01:44 Configuration on demand is an incubating feature.
....
17:43:24 The message received from the daemon indicates that the daemon has disappeared.
...

Develocity에 수집된 Gradle 빌드 정보

Started on 7월 9 2024 at 16:01:36 KST,
finished on 7월 9 2024 at 16:11:09 KST

Jenkins 콘솔과 Gradle의 빌드 정보 사이의 타임스탬프 값이 약 1시간 30분 정도 다르다는 것을 확인한 뒤 어느 것이 정확한 정보인지 확인하기 위해 빌드 출력을 파이프 명령어(|)로 수집해 타임스탬프를 추가로 출력하는 간단한 코드를 작성했습니다.

timestamp.py

import time
import sys
 
for line in sys.stdin:
    timestamp = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime())
    print(f"{timestamp} {line[:-1]}")

위 코드로 임의의 명령을 실행해 파이프 명령어로 출력을 가공하면 다음과 같은 결과를 얻을 수 있습니다.

ls | python3 timestamp.py
2024-10-04 12:25:50 AndroidStudioProjects
2024-10-04 12:25:50 Applications
2024-10-04 12:25:50 Desktop
2024-10-04 12:25:50 Documents
2024-10-07 12:25:50 Downloads

위와 같은 방법으로 실행 시간을 검증한 결과 Jenkins 콘솔에 출력되는 타임스탬프와 Develocity에 수집된 Gradle 빌드 정보 사이에 약 30분 이상의 시차가 발생한다는 것을 확인했습니다. 또한 여러 정황을 살피던 중 현재 빌드 로그의 양이 문제 발생 이전과 비교해 두 배 이상 증가했다는 것을 파악했습니다.

현재 저희가 사용하는 CI 구성에서 로그를 처리하는 부분은 Devlocity로 로그를 전송하는 부분과 Logstash를 사용해서 Elasticsearch로 전송하는 부분, 이렇게 두 부분이 있는데요. 앞서 말씀드린 것처럼 Devlocity로 전송하는 부분은 --no-scan 옵션을 적용해 테스트했을 때 아무런 변화가 없었으므로 이번에는 Logstash를 사용하지 않도록 설정을 변경했더니 더 이상 문제가 발생하지 않았습니다.

해결 방안 적용 및 문제 발생 원인 분석

여기까지의 상황을 종합해 문제를 정리해 보니 다음과 같은 결론에 도달할 수 있었습니다.

현재 발생하는 로그의 양이 Logstash에서 감당할 수 있는 수준 이상이다.

이 문제를 근본적으로 해결하는 방법은 로그 수집 성능을 높이는 것이지만 인프라 비용 문제 때문에 쉽게 선택할 수는 없었습니다. 이에 차선책으로 어떻게 하면 로그양을 줄일 수 있을지 고민했는데요. 저희는 Jenkins에 출력되는 빌드 로그 중 대부분의 내용이 정상적으로 빌드가 진행된 것을 기록한 로그라는 것에 주목했습니다.

그렇다면 '오류 메시지만 출력하면 문제를 해결할 수 있지 않을까'라고 생각했고, Gradle Logging options 문서를 참고해 로그 레벨을 'QUIET(-q)' 옵션으로 설정하면 오류 메시지만 저장할 수 있다는 점을 찾았습니다. 이를 적용한 뒤 테스트를 진행한 결과 다행히 타임아웃이 발생하지 않고 정상적으로 처리되는 것을 확인할 수 있었는데요. 이때 -q 옵션을 설정하면 기존 로그 레벨(LIFECYCLE 로그 레벨)에서 출력되던 빌드 스캔 정보가 출력되지 않으므로 다음과 같이 빌드 시스템을 수정해 기존처럼 Jenkins에 빌드 스캔 정보가 출력되도록 수정했습니다.

build-logic/settings/src/main/kotlin/AndroidGradleScanPlugin.kt

....
class AndroidGradleScanPlugin : Plugin<Settings> {
.....
    buildScanPublished {
        .....
        .....
        if (!logger.isLifecycleEnabled) {
            logger.quiet("\nPublishing build scan...\n$buildScanUri")
            // https://github.com/gradle/actions/blob/b51fcf4d6c62967b980aeba27b7e747d74e20c53/sources/src/resources/init-scripts/gradle-actions.build-result-capture.init.gradle#L97-L100
            getenv("GITHUB_OUTPUT")?.apply {
                File(this).writeText("build-scan-url=$buildScanUri\n")
            }
        }
    }
......

빌드 시스템 수정 전

$ ./gradlew :tasks -q
...
To see more detail about a task, run gradlew help --task <task>

빌드 시스템 수정 후

$ ./gradlew :tasks -q
...
To see more detail about a task, run gradlew help --task <task>

Publishing build scan...
https://{buildScanUri}

로그 증가 시 문제 발생 가능 지점 파악

위와 같은 방법으로 일단 문제는 해결했지만 아직 로그가 늘어난 이유는 찾지 못했습니다. 저희는 우선 CI 시스템을 다시 확인하며 로그가 늘어났을 때 문제가 될 수 있는 지점을 파악했습니다.

문제 발생 가능 지점 1: 빌드 로그 데이터 파이프라인

첫 번째로 데이터 로그를 수집하는 단계를 살펴봤습니다. 앞서 소개한 저희 CI 구성에서 Jenkins가 Logstash를 통해 Elasticsearch로 로그를 수집하는 부분을 살펴보면, 슬레이브 노드에서 빌드한 로그 데이터를 Jenkins 마스터 노드로 보내서 빌드 로그를 출력하고 이를 Logstash가 Elasticsearch로 보내는 단계를 거칩니다. 현재 80개의 Jenkins 슬레이브 노드가 있는데요. 각 노드가 동시에 한 대의 Jenkins 마스터 노드로 로그 데이터를 전송해 로그를 출력하고 이를 Logstash가 Elasticsearch로 보내므로, 로그양이 매우 많다면 부하가 걸릴 수 있을 것으로 추정됐습니다.

문제 발생 가능 지점 2: Logstash 플러그인

두 번째로 Logstash 플러그인의 처리 작업 지점입니다. 저희 CI 시스템에서는 빌드 데이터를 수집하기 위해 로그를 변환 및 필터링한 후 Elasticsearch로 데이터를 보내는데요. 이렇게 변환 및 필터링하는 단계에서도 로그의 양이 많아지면 부하가 걸릴 수 있을 것으로 추정됐습니다.

로그양이 늘어난 원인 파악

다음으로 현재 CI 시스템에서 출력되는 빌드 로그의 양을 확인하고 로그 증가의 원인을 파악했습니다.

먼저 현재 Gradle 서브 프로젝트의 개수를 확인했습니다. 확인 결과 개발 시스템을 모듈러화(참고: Modernize the development of LINE Messenger for Android)하기 전인 2020년에는 빌드 시스템에 10개가량의 Gradle 서브 프로젝트가 있었으나 2024년 현재에는 334개로 늘어났습니다. 2020년 이후 324개가 증가한 것입니다.

또한 현재의 CI 환경을 구축한 초기에는 빌드 시 출력되는 로그의 양이 한 서브프로젝트당 400줄 정도였는데요. 서브 프로젝트 수와 함께 각 서브 프로젝트의 로그양도 증가해 2024년에 Develocity에 수집된 빌드 로그의 길이는 23000줄 이상이었으며, 크기도 1.2MB가량이었습니다.

	2020년	2024년
Gradle 서브 프로젝트 개수	~10개	334개
추정 빌드 로그양	~400줄	~23000줄

서브 프로젝트의 출력 내용이 증가한 이유는 빌드 로그뿐 아니라 아래와 같이 Java나 Kotlin의 컴파일러와 개발 도구(예: KSP(Kotlin Sympol Processing), 린트(lint))가 제공하는 정보까지 함께 수집하고 있었기 때문이었습니다.

일부 Java 컴파일러 경고 로그

> Task :....:compileDebugJavaWithJavac
Note: Some input files use or override a deprecated API.
Note: Recompile with -Xlint:deprecation for details.
Note: Some input files use unchecked or unsafe operations.
Note: Recompile with -Xlint:unchecked for details.

AndroidManifest 경고 로그

> Task :app:.....
Namespace '.....' is used in multiple modules and/or libraries: :..., :.... Please ensure that all modules and libraries have a unique namespace. For more information, See https://developer.android.com/studio/build/configure-app-module#set-namespace

리소스 경고 로그

> Task :app:......
warn: removing resource ...... without required default value.
warn: removing resource ...... without required default value.
warn: removing resource ...... without required default value.
warn: removing resource ...... without required default value.
warn: removing resource ...... without required default value.

단위 테스트 실행 결과 로그

OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended

로그양을 늘려 타임스탬프 차이가 발생하는 상황 재현

저희는 로그양의 증가가 Develocity에 수집된 타임스탬프와 Jenkins 로그에 출력된 타임스탬프의 차이를 만들 수 있는지 확인하기 위해 테스트를 진행했습니다.

현상을 재현하기 위한 테스트 코드 작성

실제로 많은 로그가 출력될 때 현상이 발생하는지 확인하기 위해 아래와 같이 더미 로그를 출력하는 더미 출력 프로그램을 작성해 테스트를 진행했습니다.

print.py

#!/usr/bin/env python3
import argparse
import atexit
import re
import time

argparser = argparse.ArgumentParser()
argparser.add_argument("-ts", "--timestamp", action="store_true", help="Print timestamp")
argparser.add_argument("size", type=str, default = "0", nargs='?', help="Size of the dummy log per line")
args = argparser.parse_args()

def parse_size(args):
    size = args.size.lower()
    units = {"": 1, "b": 1, "k": 2 ** 10, "kb": 2 ** 10, "m": 2 ** 20,  "mb": 2 ** 20}
    m = re.match(r'^(\d+(?:\.\d+)?)\s*([km]?b?)?$', size)
    if not m:
        raise ValueError("Invalid human size")

    number, unit = m.groups()
    return int(float(number)*units[unit])


BACKSPACE = chr(0x08)
DUMMY = ("d" + BACKSPACE) * parse_size(args)

def print_timestamp(content):
    if args.timestamp:
        timestamp = time.strftime("%H:%M:%S", time.localtime()) + " - "
    else:
        timestamp = ""
    print(f"{timestamp}{content}")

def main():
    for _ in range(5):
        print_timestamp(f"dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended {DUMMY}")

def onexit():
    print_timestamp(f"dummy log: Exiting...")


if __name__ == "__main__":
    atexit.register(onexit)
    main()

위 코드는 같은 더미 로그를 한 줄씩 다섯 번 출력합니다. 이때 옵션으로 각 줄마다 타임스탬프를 출력하거나 출력하는 더미 로그 한 줄의 크기를 변경할 수 있습니다. 아래는 더미 출력 프로그램을 실행한 결과입니다.

$ ./print.py
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: Exiting...

더미 출력 프로그램을 실행할 때 아래와 같이 time 명령을 사용하면 더미 출력 프로그램의 수행 시간 및 CPU 사용량을 측정할 수 있습니다.

$ time ./print.py
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
dummy log: Exiting...
./print.py  0.02s user 0.01s system 89% cpu 0.033 total

time 명령어로 출력된 로그의 의미는 다음과 같습니다.

0.02s user: 사용자 공간(라이브러리 등)에서 사용한 CPU 사용 시간
- Python 초기화 시간(I/O 제외)
- 문자열 형식화 수행 시간
0.01s system: 시스템 호출 수행에 사용한 CPU 시간
- Python 초기화 중 표준 라이브러리 로딩(I/O) 시간
- 표준 출력으로 데이터 전송 시 write 시스템 호출 사용
0.033 total : 프로그램을 수행하는 동안 소요된 사용자 공간과 시스템 호출과 유휴 시간을 모두 합친 시간
- 89% cpu: 전체 시간 동안의 평균 CPU 사용률

다음으로 입력받은 내용을 한 줄씩 출력하면서 타임스탬프를 보여주는 다음과 같은 간단한 코드를 만들었습니다. 한 줄씩 출력할 때마다 입력받은 타임아웃 시간만큼 sleep을 실행할 수 있습니다.

ts.py

#!/usr/bin/env python3
# vim: ts=4 sw=4 sts=4 et ai

import sys
import time
if len(sys.argv) > 1:
    timeout = int(sys.argv[1])
else:
    timeout = 0

for line in sys.stdin:
    timestamp = time.strftime("%H:%M:%S")
    print(f"{timestamp} | {line}", end="")
    time.sleep(timeout)

여기서 파이프 명령어를 이용해 더미 출력 코드의 타임스탬프를 출력하면 더미 로그가 출력될 때마다 타임스탬프가 함께 출력됩니다.

$ time ./print.py | ./ts.py
10:11:53 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:11:53 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:11:53 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:11:53 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:11:53 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:11:53 | dummy log: Exiting...
./print.py  0.02s user 0.01s system 91% cpu 0.032 total
./ts.py  0.02s user 0.01s system 67% cpu 0.033 total

아래는 타임스탬프 기능이 잘 작동하는지 타임아웃 시간 1초를 입력해서 테스트해 본 결과입니다. 더미 출력 프로그램의 수행 시간은 이전과 비교해 크게 달라지지 않았지만(0.033초 → 0.027초), 타임스탬프를 출력하는 코드가 각 줄을 출력할 때마다 1초씩 쉬어서 총 6.058초가 걸린 것을 확인할 수 있습니다.

$ time ./print.py | ./ts.py 1
10:12:39 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:12:40 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:12:41 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:12:42 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:12:43 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
10:12:44 | dummy log: Exiting...
./print.py  0.02s user 0.01s system 92% cpu 0.027 total
./ts.py 1  0.02s user 0.01s system 0% cpu 6.058 total

테스트 코드를 이용해 현상 재현

이제 현재 CI 시스템에서 Jenkins 슬레이브에서 작동하는 빌드 로그가 출력되는 상황을 재현할 준비가 완료됐습니다.

그런데 단순히 로그 출력하는 부분에 지연을 추가하는 것으로는 현상이 재현되지 않습니다. 그 이유를 알기 위해서는 파이프 명령어와 입출력 시스템의 특성을 이해해야 하는데요. 대부분의 입출력 시스템에는 버퍼나 캐시가 존재합니다. Linux 문서를 살펴보면 V2.6.11 이상부터 파이프의 용량이 65,536 바이트인 것을 확인할 수 있습니다.

In Linux versions before 2.6.11, the capacity of a pipe was the same as the system page size 
(e.g., 4096 bytes on i386). 
Since Linux 2.6.11, the pipe capacity is 65536 bytes.

따라서 이에 맞춰 로그 출력양을 파이프의 버퍼 크기인 64KB로 늘리고 파이프 출력에 1초의 지연을 추가하면 더미 출력 프로그램의 수행 시간이 0.079초에서 4.094초로 늘어난 것을 확인할 수 있습니다.

$ time ./print.py 64k
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
dummy log: Exiting...
./print.py 64k  0.02s user 0.02s system 47% cpu 0.079 total

$ time ./print.py 64k | ./ts.py 1
11:31:42 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:31:43 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:31:44 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:31:45 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:31:46 | dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:31:47 | dummy log: Exiting...
./print.py 64k  0.03s user 0.01s system 0% cpu 4.094 total
./ts.py 1  0.02s user 0.02s system 0% cpu 6.113 total

이제 더미 출력 프로그램에도 직접 타임스탬프가 나오도록 설정한 후 실행하면, 저희가 겪은 문제 상황처럼 Develocity에 수집된 타임스탬프와 Jenkins 로그에 출력된 타임스탬프가 달라지는 것을 확인할 수 있습니다. 즉, Gradle 빌드는 Develocity에서 이미 완료됐지만, Gradle 빌드 중 생성된 로그를 Jenkins 화면에 보여주기 위해 로그 데이터를 전송할 때 버퍼 크기 만큼씩 로그 내용을 처리하느라 지연이 발생한 것입니다.

$ time ./print.py -ts | ./ts.py 1
11:35:35 | 11:35:35 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
11:35:36 | 11:35:35 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
11:35:37 | 11:35:35 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
11:35:38 | 11:35:35 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
11:35:39 | 11:35:35 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
11:35:40 | 11:35:35 - dummy log: Exiting...
./print.py -ts  0.02s user 0.01s system 93% cpu 0.028 total
./ts.py 1  0.02s user 0.01s system 0% cpu 6.057 total

$ time ./print.py -ts 64k | ./ts.py 1
11:35:49 | 11:35:49 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:35:50 | 11:35:49 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:35:51 | 11:35:50 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:35:52 | 11:35:51 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:35:53 | 11:35:52 - dummy log: OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended d
11:35:54 | 11:35:53 - dummy log: Exiting...
./print.py -ts 64k  0.03s user 0.01s system 0% cpu 4.095 total
./ts.py 1  0.02s user 0.02s system 0% cpu 6.113 total

이와 같은 과정을 거쳐 저희가 겪은 문제의 원인이 로그양의 증가라는 가설을 검증할 수 있었습니다.

마치며

표준 입출력(print)으로 사용자에게 로그 내용을 보여주는 CI 빌드 환경을 구성한 경우 표준 입출력의 버퍼 크기보다 큰 로그를 출력하면 해당 작업이 완료될 때까지 기다려야 하므로 블로킹이 발생할 수 있습니다. 이에 따라 로그의 양이 CI 빌드 속도에 영향을 미칠 수 있습니다.

Gradle 빌드를 사용하는 저희의 경우 경고 및 오류만 출력하는 Gradle의 -q 옵션을 사용해 로그의 크기를 1.2MB에서 124KB로 1/10로 줄일 수 있었습니다. 현재 Grafana에서 로그를 분석할 때 경고 및 오류 메시지만 활용하고 있기 때문에 이와 같은 조치가 로그 분석 결과에 영향을 미치지는 않았습니다. 다만 기존에 Developcity에서 빌드 로그 결과를 확인할 수 있는 Gradle 스캔 URL을 빌드 로그에 출력할 수 있도록 빌드 스크립트를 수정하는 과정은 추가로 필요했습니다.

로그양이 줄어들면서 Logstash의 부하도 줄어 기존에 존재했던 잠재적 오버헤드 또한 줄어들었습니다. -q 옵션 추가 후 Jenkins의 빌드 수행 시간이 기존보다 짧아짐 : 30분 → 10분 이를 통해 불필요한 로그는 굳이 출력하지 않는 것이 좋다는 것을 알 수 있었습니다.

이번 이슈를 해결하면서 CI 시스템을 구성하고 운영하면서 몇 가지 놓치지 말아야 할 점을 정리해 봤습니다.

문제를 인지할 수 있는 기준을 명확하게 정의해두자.
- 너무 빈번한 알람은 문제를 숨길 수 있다.
- 진짜 문제가 될 만한 내용에 대해서만 경고를 남긴다.
- 자주 발생하는 문제는 반드시 빠른 시간 안에 처리한다.
문제 발생 여지가 있는 부분은 로그를 남기자.
- 단, 의미 없는 로그의 양이 증가하면 정작 필요한 로그를 확인하기 힘들게 만들어 오히려 처리를 지연시켜 문제를 키우거나 감출 수 있다.
- 'Warning, Debug, Error, Info'와 같이 시스템에서 제공하는 로그 레벨 옵션을 적절히 사용해 필요할 때만 로그가 출력되도록 설정한다.
한 번에 해결되는 문제는 없다.
- 문제를 확인하고 분석하는 과정에서 문제를 여러 부분으로 나눠 각 부분을 하나씩 해결하면 그 결과를 조화롭게 이용할 수 있다.
- 즉, 문제를 분할 정복한다.

이번 이슈의 경우 근본적으로 해결하려면 메시지 전달 방법을 다시 고민하거나 애플리케이션 자체에서 로그를 줄이는 방법을 시도해야 합니다. 하지만 이 두 방법은 많은 비용이 필요하며, 로그를 필요로 하는 각 개발 조직의 이해관계도 맞물려 있기 때문에 쉽게 선택할 수 없는 방법입니다. 이 글이 그와 같은 상황에서 고민하고 있는 분들께 도움이 되기를 바라며 이만 마치겠습니다.

참고 자료

CI 빌드 오류의 원인 분석에서 해결까지의 여정

댓글