grep

Engineering

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

라인

2025년 1월 6일

원문에서 보기 ↗

들어가며

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

CI 구성 소개

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

image 각 도구 소개

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

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

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

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

빌드 실패 원인 탐색

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

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

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) 개수와 메모리 할당량을 다음과 같이 조정해 봤지만 문제는 해결되지 않았습니다.

타임스탬프 차이 발견

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

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를 사용하지 않도록 설정을 변경했더니 더 이상 문제가 발생하지 않았습니다.

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

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

이 문제를 근본적으로 해결하는 방법은 로그 수집 성능을 높이는 것이지만 인프라 비용 문제 때문에 쉽게 선택할 수는 없었습니다. 이에 차선책으로 어떻게 하면 로그양을 줄일 수 있을지 고민했는데요. 저희는 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로 보내므로, 로그양이 매우 많다면 부하가 걸릴 수 있을 것으로 추정됐습니다.

image

문제 발생 가능 지점 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 명령어로 출력된 로그의 의미는 다음과 같습니다.

다음으로 입력받은 내용을 한 줄씩 출력하면서 타임스탬프를 보여주는 다음과 같은 간단한 코드를 만들었습니다. 한 줄씩 출력할 때마다 입력받은 타임아웃 시간만큼 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 슬레이브에서 작동하는 빌드 로그가 출력되는 상황을 재현할 준비가 완료됐습니다.

image

그런데 단순히 로그 출력하는 부분에 지연을 추가하는 것으로는 현상이 재현되지 않습니다. 그 이유를 알기 위해서는 파이프 명령어와 입출력 시스템의 특성을 이해해야 하는데요. 대부분의 입출력 시스템에는 버퍼나 캐시가 존재합니다. 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분 이를 통해 불필요한 로그는 굳이 출력하지 않는 것이 좋다는 것을 알 수 있었습니다.

image

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

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

참고 자료