May 29, 2021

all posts ->

때때로 앱이 작동하지만 그 성능을 증가시키기 위해 처리량을 늘리거나 대기 시간을 줄이고 싶을 수 있습니다. 또는, 코드가 런타임에 어떻게 동작하는지 알고싶어 하거나, 핫스팟이 어디에 있는지 파악하거나, 프레임워크가 내부에서 어떻게 작동하는지 밝혀내고 싶을 수 있습니다.

이것이 바로 프로파일러를 사용하게 만드는 완벽한 유즈 케이스입니다. 그들은 임의의 큰 실행 덩어리에 대한 새의 눈 뷰를 제공하며, 이는 규모에 따른 문제를 파악하는데 도움이 됩니다.

많은 사람들은 자신들이 고부하 어플리케이션을 작성하지 않는다면 프로파일링하는 방법을 배울 필요가 없다고 믿습니다. 예시에서, 우리는 매우 간단한 어플리케이션을 다루면서도 프로파일링을 통해 어떻게 이익을 얻을 수 있는지 알아볼 것입니다.

예시 어플리케이션

다음과 같은 프로그램이 있다고 가정해봅시다:

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.*;
import java.util.concurrent.TimeUnit;

public class CountEvents {

    public static int update(Deque<Long> events, long nanos, long interval) {
        events.add(nanos);
        events.removeIf(aTime -> aTime < nanos - interval);
        return events.size();
    }

    public static void main(String[] args) throws IOException {
        long start = System.nanoTime();
        int total = 100_000;
        long interval = TimeUnit.MILLISECONDS.toNanos(100);
        int[] count = new int[total];

        Deque<Long> collection = new ArrayDeque<>();
        for (int counter = 0; counter < count.length; counter++) {
            count[counter] = update(collection, System.nanoTime(), interval);
            Path p = Paths.get("./a/b");
            Files.createDirectories(p);
        }
        long spent = System.nanoTime() - start;

        //noinspection OptionalGetWithoutIsPresent
        System.out.println("Average count: " + (int) (Arrays.stream(count).average().getAsDouble()) + " op");
        System.out.println("Spent time: " + TimeUnit.NANOSECONDS.toMillis(spent) + " ms");
    }
}

프로그램은 반복적으로 파일 시스템에서 경로를 생성하려고 시도하며 NIO2에서 createDirectories() 를 사용합니다. 그런 다음 우리는 제작한 벤치마크를 이용해 처리량을 측정합니다.

작업이 실행될 때마다, 벤치마크 로직은 현재의 타임스탬프를 컬렉션에 저장하고, 현재의 시간보다 앞서는 한 구간의 모든 타임스탬프를 제거합니다. 이를 통해 이 시간 간격 동안 얼마나 많은 이벤트가 발생했는지 단순히 컬렉션을 조회함으로써 알아낼 수 있게 됩니다. 이 벤치마크는 우리가 createDirectories() 메소드의 성능을 평가하는 데 도움이 되기 위해 설계되었습니다.

프로그램을 실행하면, 숫자들이 의심스럽게 낮다는 것을 알게 됩니다:

Average count: 6623 op
Spent time: 1462 ms

프로파일링을 해보고 어떤 문제가 있는지 살펴봅시다.

스냅샷 얻기

첫 번째로, 프로파일링 데이터를 수집해야 합니다. 이것은 스냅샷이라고도 불립니다. 이 단계에서, 프로파일러는 프로그램과 함께 실행되며 그 활동에 대한 정보를 수집합니다. 프로파일러는 이를 달성하기 위해 다양한 기법을 사용합니다. 예를 들면 메소드의 진입과 종료를 계측하는 것입니다. IntelliJ Profiler는 앱에서 실행되는 모든 스레드로부터 주기적으로 스택 정보를 수집함으로써 이를 수행합니다.

IntelliJ IDEA에서 프로파일러를 붙이려면, 보통 어플리케이션을 실행하기 위해 사용하는 실행 구성을 선택하고, 메뉴에서 프로파일 (Profile)을 선택합니다.

어플리케이션이 실행을 마치면, 스냅샷을 열라는 메시지가 나타날 것입니다. 우리가 이 팝업 메시지를 잘못 닫으면, 스냅샷은 프로파일러 (Profiler) 도구 창에서 여전히 사용 가능합니다.

보고서를 열어서 어떤 것이 들어있는지 살펴봅시다.

스냅샷 분석하기

보고서를 열자마자 보게 되는 첫 번째 것은 플레임 그래프입니다. 이것은 기본적으로 모든 샘플링된 스택들의 요약입니다. 프로파일러가 동일한 스택을 가진 샘플을 수집한 만큼, 플레임 그래프에서 이 스택의 너비가 넓어집니다. 그래서, 프레임의 너비는 대략적으로 이 상태에서 보낸 시간의 비율에 해당합니다.

우리는 놀랍게도 createDirectories() 메소드가 가장 많은 실행 시간을 차지하지 않았습니다. 우리의 집 만들기 벤치마크는 실행하는데 동일한 시간을 소비했습니다!

더욱이, 우리가 위의 프레임을 살펴보면, 이것은 주로 removeIf() 메소드 때문인 것으로 보입니다. 이 메소드는 호출자인 update() 의 대부분의 시간을 차지합니다.

이것은 확실히 조사해볼 필요가 있습니다.

벤치마크 최적화

대기열에서 이벤트를 제거하는 코드가 추가 작업을 하는 것처럼 보입니다.

우리는 순서를 가진 컬렉션을 사용하고 있고, 이벤트들은 시간 순서대로 추가되기 때문에, 우리는 제거 대상인 모든 요소들이 항상 대기열의 앞쪽(head)에 있다는 것을 확실히 알 수 있습니다. 만약 우리가 removeIf() 를 제거하려고 하는 이벤트에 도달하게 되면 반복을 멈추는 루프와 교체한다면, 우리는 성능을 향상시킬 수 있을 것입니다:

// events.removeIf(aTime -> aTime < nanos - interval);
while (events.peekFirst() < nanos - interval) {
    events.removeFirst();
}

코드를 변경하고 다시 어플리케이션을 프로파일링하여 결과를 살펴봅시다:

벤치마크 로직에서 발생하는 오버헤드는 이제 최소화되어야 하며, createDirectories() 프레임은 이제 전체 실행 시간의 약95%를 차지하고 있습니다.

개선 사항은 콘솔 출력에서도 보입니다:

Average count: 14788 op
Spent time: 639 ms

네이티브 프로파일링

벤치마크에서 문제를 해결한 후에, 여기서 멈추고 우리 자신에게 박수를 칠 수 있습니다. 하지만 우리의 createDirectories() 메소드에서는 어떤 일이 일어나고 있는 걸까요? 너무 느린가요?

여기서 최적화 할 수 있는 여지는 거의 없어 보입니다. 왜냐하면 이것은 라이브러리 메소드이며, 우리는 그 구현에 대한 제어권이 없기 때문입니다. 그래도, 프로파일러는 우리에게 힌트를 줄 수 있습니다.

접힌 라이브러리 프레임을 펼쳐서 안에 무슨 일이 일어나는지 살펴볼 수 있습니다.

이 플레임 그래프의 부분에서 보게되면, createDirectories() 의 실행 시간에 가장 큰 기여를 한 것은 sun.nio.fs.UnixNativeDispatcher.mkdir0 임을 알 수 있습니다. 이 프레임의 큰 부분은 위에 아무 것도 없습니다. 이것은 메소드의 self-time이라고 불리며, 이는 그 이상의 자바 코드가 없음을 나타냅니다. 그러나 네이티브 코드가 있을 수 있습니다.

디렉토리를 생성하려고 시도하고 있기 때문에, 우리는 운영 체제의 API를 호출해야 하므로, mkdir 의 self-time은 네이티브 호출에 의해 지배되는 것으로 예상할 수 있습니다. UnixNativeDispatcher 는 클래스 이름에서 이를 확인하는 것으로 보입니다.

네이티브 프로파일링을 활성화합시다 (설정 | 빌드, 실행, 배포 | 프로파일러 | 네이티브 호출 수집 – Settings | Build, Execution, Deployment | Java Profiler | Collect native calls):

네이티브 프로파일링이 활성화된 상태에서 애플리케이션을 다시 실행하면 전체 그림을 볼 수 있습니다:

여기서 문제점이 있습니다. createDirectories() 메소드에 대한 문서는 다음과 같이 말합니다:

이 설명은 자바 관점에서 유효하며, 자바 예외를 발생시키지 않습니다. 그러나, 이미 존재하는 디렉토리를 생성하려고 시도할 때, 운영체제 수준에서 예외가 발생합니다. 이것은 우리의 시나리오에서 중요한 자원의 낭비를 초래합니다.

이를 피하려고 createDirectories() 호출을 Files.exists() 로 확인하는것으로 감싸 봅시다:

Path p = Paths.get("./a/b");
if (!Files.exists(p)) {
    Files.createDirectories(p);
}

프로그램이 굉장히 빠르게 됩니다!

Average count: 50000 op
Spent time: 87 ms

이제 원래보다 약 16배 더 빠릅니다. 이 예외 처리는 정말로 비용이 많이 들었습니다! 결과는 하드웨어와 환경에 따라 다르지만, 그래도 인상적일 것입니다.

스냅샷의 차이

IntelliJ Profiler를 사용하는 경우, 두 스냅샷을 시각적으로 비교할 수 있는 훌륭한 도구가 있습니다. 자세한 설명과 단계에 대해서는 문서를 참조하는 것이 좋습니다. 다음은 차이가 보여주는 결과에 대한 간단한 요약입니다:

새로운 스냅샷에서 누락된 프레임들은 녹색으로 강조되며, 새로운 것들은 빨간색으로 표시됩니다. 만약 프레임이 여러 색상을 가지면, 이는 프레임이 두 스냅샷 모두에 존재하지만, 그 전체 런타임이 변경되었음을 의미합니다.

위의 스크린샷에서 볼 수 있듯이, 원래 우리의 프로그램에서 수행된 대다수의 작업들은 필요하지 않았으며, 우리는 이것들을 제거할 수 있었습니다. CountEvents.update() 는 완전히 녹색으로 보이며, 이는 우리의 첫 번째 변경이 이 메소드의 런타임에서 거의 완전한 개선을 가져왔음을 의미합니다. Files.exists() 를 추가하는 것은 100% 개선은 아니었지만, 이것은 createDirectories() 를 스냅샷에서 제거하는 데 효과적이었고, 프로그램 런타임에 오직 60ms를 추가했습니다.

결론

이 시나리오에서, 우리는 프로파일러를 이용해 성능 문제를 탐지하고 수정했습니다. 우리는 또한 친숙한 API조차도 심각하게 자바 프로그램의 실행 시간에 영향을 줄 수 있는 함의를 가지고 있을 수 있다는 것을 보았습니다. 이것은 왜 프로파일링이 초당 수백만 건의 트랜잭션에 대해 최적화를 수행하고 있지 않더라도 유용한 기술인지 보여줍니다.

다가오는 여러 가지 프로파일링 유즈 케이스와 기술에 대해 생각해 볼 예정입니다. 계속해서 눈을 뜨고 있으십시오!

all posts ->

---

• Igor Kulakov에 의해 만들어졌습니다. 즐겨주세요!

• 구독

• 
• 
• 
•