Java 메소드 실행 시간 측정하기

각 로직들에 대해 성능 테스트를 하기 전, 시간을 측정하고 로그로 남긴다면 분석시에 도움이 됩니다.

Java에서 시간을 측정하는 다양한 방법들이 있지만 다음에 대해서 우선적으로 정리합니다.

1. System.currentTimeMillis()를 사용하는 방법
2. System.nanoTime()를 사용하는 방법
3. Spring StopWatch를 사용하는 방법
4. Guava의 Stopwatch를 사용하는 방법
5. Apache Commons Lang의 StopWatch를 사용하는 방법

모든 클래스가 thread-safe하진 않으므로 주의해서 사용해야 한다는 단점이 있습니다.

개인적으로 Spring StopWatch가 가장 사용하기 좋고 편리하였습니다.

이를 AOP나 Interceptor 등과 같이 유용하게 이용할 수 있습니다.

시간을 다양한 단위로 표현하는 데 사용되는 단위들은 다음과 같습니다:

1. 나노초 (Nanoseconds): 1초를 10억(1,000,000,000) 나노초로 표현
2. 마이크로초 (Microseconds): 1초를 백만(1,000,000) 마이크로초로 표현
3. 밀리초 (Milliseconds): 1초를 천(1,000) 밀리초로 표현
4. 초 (Seconds): 일반적으로 시간의 기본 단위로 사용
5. 분 (Minutes): 1분은 60초로 구성되며, 1시간을 60분으로 표현
6. 시간 (Hours): 1시간은 60분 또는 3,600초로 구성
7. 일 (Days): 1일은 보통 24시간 또는 86,400초로 구성

1. System.currentTimeMillis()를 사용하는 방법

System.currentTimeMillis()는 현재 시간을 ms로 반환합니다.

Epoch 시간이라고도 알려진 1970년 1월 1일 00:00:00 UTC부터 현재까지 경과한 시간을 밀리초 단위의 long 타입으로 로 반환합니다

UTC 라는 시간 표준 체계를 따릅니다.

• Coordinated Universal Time의 약자입니다.
• UTC+9:00 ( UTC+9 )는 대한민국의 표준시로, 한국 표준시간대(KST)로 알려진 시간대를 가리킵니다. 대한민국의 로컬 시간은 UTC보다 9시간 빠른 시간을 나타냅니다.

따라서 호출 할 때마다 값이 다를 수 있으며 이 시간 값을 변환하여 현재 날짜를 구할 수도 있습니다.

class TimeMeasuringApplicationTests {
    private Service service = new Service();


    @Test
    void currentTimeTest() {

    long startTime = System.currentTimeMillis();
        service.logic0_05Sec(); // 0.05초 걸리는 로직 실행 
        long endTime = System.currentTimeMillis();

        long timeElapsed = endTime - startTime;

        System.out.println("milli seconds : " +  timeElapsed);
        System.out.println("seconds : " + (double)timeElapsed / 1000);
    }
}

결과

milli seconds : 56
seconds : 0.056

2. System.nanoTime()를 사용하는 방법

System.nanoTime() 로 나노초로 시간을 측정할 수 있습니다.

1ms 이하의 nano 수행 시간 측정을 위해 만들어진 메소드 입니다.

class TimeMeasuringApplicationTests {
    private Service service = new Service();

    @Test
    void systemNanoTimeTest() {

        long startTime = System.nanoTime();
        service.logic0_05Sec(); // 0.05초 걸리는 로직 실행 
        long endTime = System.nanoTime();

        long timeElapsed = endTime - startTime;

        System.out.println("nano seconds :" +  timeElapsed);
        System.out.println("milli seconds: " + timeElapsed / 1000000);
        System.out.println("seconds : " + (double)timeElapsed / 1_000_000_000);
    }
}

결과

nano seconds :56878083
milli seconds: 56
seconds : 0.056878083

3. Spring StopWatch를 사용하는 방법

Spring에서 제공하는 간단한 StopWatch 클래스입니다.

내부적으로 System.nanoTime() 사용을 숨겨 코드의 가독성을 높이고 계산 오류 가능성도 줄여줍니다.

그러나 thread-safe하지 않으며 동기화를 사용하지 않습니다. 때문에 주의해서 사용해야 합니다.

StopWatch는 일반적으로 프로덕션 애플리케이션의 일부로 쓰진 않고, 개발 중에 성능을 확인하는 데 사용됩니다.

Spring 5.2부터는 실행 시간이 나노초(ns) 단위로 추적되고 보고됩니다.

사용방법은 간단합니다.

객체를 생성하고, start()와 stop() 사이에 로직을 실행시키면 됩니다.

또한 각각의 작업을 구분하기 위해 id를 지정할 수도 있으며,

start() 시에 task 이름을 지정할 수도 있습니다.

import org.springframework.util.StopWatch;

class TimeMeasuringApplicationTests {

  private Service service = new Service();

  @Test
    void springStopWatchTest() {

        StopWatch stopWatch = new StopWatch("thread1 - GET /api/users/1");

    stopWatch.start("0.05초 걸리는 유저 조회 시간 측정");
        service.logic0_05Sec(); // 0.05초 걸리는 로직 실행 
        stopWatch.stop();

        System.out.println(stopWatch.prettyPrint());
        System.out.println("마지막 작업 걸린 시간 : " + stopWatch.getLastTaskTimeNanos());
        System.out.println("totalTimeSeconds : " + stopWatch.getTotalTimeSeconds());

        System.out.println("------------------");

        stopWatch.start("0.1초 걸리는 유저 조회 시간 측정");
        service.logic0_1Sec(); // 0.1초 걸리는 로직 실행 
        stopWatch.stop();

        System.out.println(stopWatch.prettyPrint());
        System.out.println("마지막 작업 걸린 시간 : " + stopWatch.getLastTaskTimeNanos());
        System.out.println("totalTimeSeconds : " + stopWatch.getTotalTimeSeconds());
    }
}

실행 결과

// 첫 번째 호출
StopWatch 'thread1 - GET /api/users/1': running time = 51231375 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
051231375  100%  0.05초 걸리는 유저 조회 시간 측정

마지막 작업 걸린 시간 : 51231375
totalTimeSeconds : 0.051231375

------------------------------------------------------------------------------------
// 두 번째 호출 
StopWatch 'thread1 - GET /api/users/1': running time = 156259958 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
051231375  033%  0.05초 걸리는 유저 조회 시간 측정
105028583  067%  0.1초 걸리는 유저 조회 시간 측정

마지막 작업 걸린 시간 : 105028583
totalTimeSeconds : 0.156259958

• 전체 해당 StopWatch의 소요시간을 보여주고, 각각의 Task를 작업하는데 걸린 시간과 비중을 보여줍니다.
• StopWatch의 id는 "thread1 - GET /api/users/1" 이며, Task를 각각 지정해줬습니다.
• 첫번째 작업은 0.05초 걸렸고, 두번째 작업은 0.1초 걸린것을 볼 수 있습니다.
  • 두 로직을 비교했을 때 두번째 0.1초 걸리는 로직이 더 오래 걸린다는 것을 알 수 있습니다.
• totalTimeSeconds는 같은 StopWatch 객체를 두번 사용했기 때문에 총 합산 시간이 나오게 됩니다.

StopWatch는 Thread-safe 하지 않아서 다음처럼 사용할 수도 있습니다.

class TimeChecker {
  private static final ThreadLocal<StopWatch> threadLocalStopWatch = 
    ThreadLocal.withInitial(StopWatch::new);

  public void 측정() {
    StopWatch stopWatch = threadLocalStopWatch.get();
    stopWatch.start();

    // 실행 시간을 측정해야하는 작업
    stopWatch.stop();
    System.out.println("Execution time: " + stopWatch.getTotalTimeMillis() + " milliseconds");
    // ThreadLocal 변수 정리
    threadLocalStopWatch.remove();
    }
}

• 각 스레드는 자체 StopWatch 인스턴스를 사용하고, 실행 시간을 측정한 후 StopWatch를 초기화합니다.

또한 StopWatch가 System.out.println()으로 찍는것이 불편하다면, logger를 이용해도 됩니다.

4. Guava의 StopWatch를 사용하는 방법

google의 guava 라이브러리에서 사용할 수 있는 stopwatch 클래스 입니다.

guava의 Stopwatch 클래스도 thread-safe 하지 않으며 간단히 코드의 실행 시간을 측정할 수 있습니다.

주요 기능은 다음과 같습니다:

• createStarted(): 실행 시간 측정을 시작한 상태로 Stopwatch 인스턴스를 생성합니다.
• start(): 실행 시간 측정을 시작합니다.
• stop(): 실행 시간 측정을 중지합니다.
• reset(): 실행 시간을 초기화합니다.
• elapsed(TimeUnit): 경과 시간을 주어진 시간 단위로 반환합니다.
• elapsedMillis(): 경과 시간을 밀리초 단위로 반환합니다.
• isRunning(): Stopwatch가 실행 중인지 여부를 반환합니다.

의존성 추가

// https://mvnrepository.com/artifact/com.google.guava/guava
implementation 'com.google.guava:guava:31.1-jre'

사용

import com.google.common.base.Stopwatch;
class TimeMeasuringApplicationTests {
    private Service service = new Service();

    @Test
    void guavaStopWatchTest() {

        // Stopwatch.createUnstarted(); start() 를 호출하려면 이렇게 생성 

        Stopwatch stopwatch = Stopwatch.createStarted();

        service.logic0_05Sec();
        stopwatch.stop();

        System.out.println(stopwatch.toString());
        System.out.println("nano seconds : " + stopwatch.elapsed(TimeUnit.NANOSECONDS));
        System.out.println("micro seconds : " + stopwatch.elapsed(TimeUnit.MICROSECONDS));
    }
}

결과

50.17 ms
nano seconds : 50167833
micro seconds : 50167

• createStarted() 또는 createUnstarted() 정적 팩토리 메소드를 이용하여 생성합니다.
• createStarted() 로 생성하면 생성하자마자 시작됩니다. 때문에 start()를 호출하면 예외가 발생합니다.
• start()를 명시적으로 호출하려면 createUnstarted() 로생성해야 합니다.
• 만약 처음부터 재사용 하고 싶다면, reset() 메소드를 호출하면 됩니다.

5. Apache Commons Lang의 StopWatch를 사용하는 방법

Apache Commons Lang에서 제공하는 StopWatch 클래스 입니다.

• https://commons.apache.org/proper/commons-lang/apidocs/org/apache/commons/lang3/time/StopWatch.html

의존성 추가

// https://mvnrepository.com/artifact/org.apache.commons/commons-lang3
implementation 'org.apache.commons:commons-lang3:3.12.0'

Spring StopWatch에 비해 조금 더 경량화 되어 있다는 장점이 있습니다.

다만, Start(), stop(), reset(), suspend(), resume() 등의 메소드를 제공해주므로 상태가 있다고 판단할 수 있고 때문에 규칙이 있습니다

Spring StopWatch와는 다르게 taskName을 지정할 수 없습니다.

1. split(), suspend() 또는 stop()은 두 번 호출할 수 없습니다.
2. watch가 split()된 경우에만 unsplit()을 호출할 수 있습니다.
3. resume()는 시계가 suspend()된 경우에만 호출할 수 있습니다.
4. reset()을 호출하지 않고 start()를 두 번 호출할 수 없습니다.

import org.apache.commons.lang3.time.StopWatch;

class TimeMeasuringApplicationTests {
    private Service service = new Service();

    @Test
    void apacheStopWatchTest() {

        StopWatch stopWatch = new StopWatch("thread1 - GET /api/users/1");
        stopWatch.start();

        service.logic0_05Sec(); // 0.05초 걸리는 로직 실행 

        stopWatch.stop();

        System.out.println(stopWatch.toString());
        System.out.println("메시지 : " + stopWatch.getMessage() + ", 소요시간 : " + stopWatch.getTime());
    }
}

결과

thread1 - GET /api/users/1 00:00:00.052
메시지 : thread1 - GET /api/users/1, 소요시간 : 52

• toString으로 message와 소요시간을 알 수 있습니다.
• getTime()으로 소요시간을 측정한 값이 나옵니다. start와 stop 사이의 소요 시간을 반환합니다. (52초 아니에요!! )