2. 내가 만든 프로그램의 속도를 알고 싶다

2. 내가 만든 프로그램의 속도를 알고 싶다

시스템의 성능이 느릴 때 가장 먼저 해야 하는 작업은 병목 지점을 파악하는 것이다. 자바 기반의 시스템에 대하여 응답 속도나 각종 데이터를 측정하는 프로그램은 많다. 애플리케이션의 속도에 문제가 있을 때 분석하기 위한 툴로는 프로파일링 툴이나 APM 툴이 있다. 이 툴을 사용하면, 고속도로 위에서 헬기나 비행기로 훑어보듯이 병목 지점을 쉽게 파악할 수 있다. 하지만 대부분의 프로젝트나 운영 사이트에서는 예산상의 이유로 분석 툴을 사용하지 않는다. 이러한 현실에서 우리가 할 수 있는 방법에 대해서 알아보자.

1. 프로파일링 툴이란?

• 프로파일링 툴은 시스템 문제 분석 툴이라고 이해하면 된다.
• 요즘 많이 사용하는 툴로는 APM(Application Performance Mornitoring 혹은 Management)이 있다.
• 국산 APM은 미소 정보사의 WebTune, 케이와이즈사의 Pharos, 외산으로는 CA Wily의 Introscope, Compuware의 dynaTrace라는 툴이 존재하고, 이 툴들은 운영용 서버를 진단 및 모니터링하기 위해서 사용된다. 이 중에 미소 정보사의 WebTune은 개발 장비에서 사용하는 라이선스가 무료다.
• APM 툴을 프로파일링 툴과 비교하면 프로파일링 툴은 개발자용 툴이고, APM 툴은 운영 환경용 툴이라고 할 수 있다.

• 프로파일링 툴은 대부분 느린 메서드, 느린 클래스를 찾는 것을 목적으로 하지만, APM 툴은 목적에 따라 용도가 상이하다. 어떤 APM 툴은 문제점 진단에 강한 한편, 다른 APM 툴은 시스템 모니터링 및 운영에 강하다.
• 자바 기반의 애플리케이션을 분석하는 프로파일링 툴은 상용과 비 상용으로 나뉜다. 대표적인 상용 툴로는 퀘스트 소프트웨어의 JProbe와 ej-technologies의 JProfiler, YourKit의 YourKit이라는 툴이 있다. 비 상용 툴은 굉장히 많은데, 대표적인 비 상용 툴들은 대부분 개발 툴과 연계해서 사용하도록 되어 있다. 넷빈즈에서 사용하는 프로파일러가 있고, 이클립스(Eclipse)에서 사용하는 TPTP(Eclipse Test & Performance Tools Platform)도 있다.

그럼 프로파일링 툴이 기본적으로 제공하는 기능은 어떤 것들이 있을까? 각 툴이 제공하는 기능은 다양하고 서로 상이하지만, 응답 시간 프로파일링과 메모리 프로파일링을 기본적으로 제공한다.

• 응답 시간 프로파일링
  응답 시간 프로파일링을 하는 주된 이유는 응답 시간을 측정하기 위함이다. 하나의 클래스에서 사용되는 메서드 단위의 응답 시간을 측정한다. 툴에 따라서 소스 라인 단위로 응답 속도를 측정할 수도 있다. 응답 시간 프로파일링을 할 때는 보통 CPU 시간과 대기 시간, 이렇게 두 가지 시간이 제공된다.
• 메모리 프로파일링
  메모리 프로파일링을 하는 주된 이유는 잠깐 사용하고 GC의 대상이 되는 부분을 찾거나, 메모리 부족 현상(Memory Leak)이 발생하는 부분을 찾기 위함이다. 클래스 및 메서드 단위의 메모리 사용량이 분석된다. 마찬가지로 툴에 따라서 소스 라인 단위의 메모리 사용량도 측정할 수 있다.

CPU 시간과 대기 시간

• CPU 시간과 대기 시간이란 하나의 메서드, 한 라인을 수행하는데 사용되는 시간은 무조건 CPU 시간과 대기 시간으로 나뉜다.
• CPU 시간은 CPU를 점유하는 시간을 의미하고, 대기 시간은 CPU를 점유하지 않고 대기하는 시간을 의미한다.
• 따라서 CPU 시간과 대기 시간을 더하면 실제 소요 시간(Clock time)이 된다. CPU 시간은 툴에 따라서 스레드(Thread) 시간으로 표시되기도 한다. 해당 스레드에서 CPU를 점유한 시간이기 때문에 표현만 다르지 사실은 같은 시간이다.

프로파일링 툴에 대해서 한가지 더 덧붙이면, APM 툴이건 프로파일링 툴이건 자동으로 분석해주는 툴은 없다. 간혹 툴만 사면 모든 것이 자동으로 해결된다는 사람들이 있는데, 잘못된 생각이다. 일단 툴에서 분석을 하려면 해당 메서드가 수행이 되어야 한다. 수행되지 않은 메서드는 분석 자체가 되지 않는다. 또한 문제가 되는 메서드가 수행되어야 하므로, 메모리 부족 현상이 가장 분석하고 찾아내기 어렵다.

더 간단하게 프로그램의 속도를 측정할 수 있는 방법은 없을까? 가장 간단하게 측정할 수 있는 방법은 System 클래스에서 제공하는 메서드를 활용하는 것이다.

2. System 클래스

모든 System 클래스의 메서드는 static으로 되어 있고, 그 안에서 생성된 in, out, err과 같은 객체들도 static으로 선언되어 있으며, 생성자(Constructor)도 없다. 다시 말하면, System 객체는 우리가 생성을 할 수 없으며, System.XXX와 같은 방식으로 써야 한다. System 클래스에서 자주 사용하지는 않지만 알아두면 매우 유용한 메서드에는 어떤 것들이 있는지 알아보자.

• static void arraycopy(Object src, int srcPos, Object dest, int destPos, int length)
  특정 배열을 복사할 때 사용한다. 여기서 src는 복사 원본 배열, dest는 복사한 값이 들어가는 배열이다. srcPos는 원본의 시작 위치, destPos는 복사본의 시작 위치, length는 복사하는 개수이다.

package com.perf.timer;

public class SystemArrayCopy {
  public static void main(String[] args) {
    String[] arr = new String[] {"AAA", "BBB", "CCC", "DDD", "EEE"};
    String[] copiedArr = new String[3];
    System.arraycopy(arr, 2, copiedArr, 1, 2);
    for(String value : copiedArr) {
      System.out.println(value);
    }
  }
}

위 코드를 실행하면 원본 배열의 2번 위치부터 복사를 하기 때문에 'CCC'부터 복사를 시작한다. copiedArr 배열의 1번 위치부터 복사한 데이터를 저장하고, 복사하는 개수가 두 개 이기 때문에 'DDD'까지 복사를 수행한다. 결과 값은 다음과 같다.

null
CCC
DDD

여기서 만약 length를 2가 아닌 3으로 하거나 그 이상으로 지정하게 되면 copiedArr의 크기가 3개밖에 되기 않기 때문에 ArrayIndexOutOfBoundsException이 발생한다.

자바에서 JVM에서 사용할 수 있는 설정은 크게 두가지로 나뉜다. 하나는 속성(Property)값이고, 다른 하나는 환경(Environment)값이다. 속성은 JVM에서 지정된 값들이고, 환경은 장비(서버)에 지정되어 있는 값들이다. 자바에서는 영어 단어 그대로 "속성"은 Properties로, "환경"은 env로 사용한다. 먼저 Properties를 사용하는 메서드에 대해서 알아보자.

• static Properties getPropeties()
  현재 자바 속성 값들을 받아온다.
• static String getProperty(String key)
  key에 지정된 자바 속성 값들을 받아온다.
• static String getProperty(String key, String def)
  key에 지정된 자바 속성 값들을 받아 온다. def는 해당 key가 존재하지 않을 경우 지정할 기본값이다.
• static void setProperties(Properties props)
  props 객체에 담겨 있는 내용을 자바 속성에 지정한다.
• static String setProperty(String key, String value)
  자바 속성에 있는 지정된 key의 값을 value 값으로 변환한다.

이러한 자바 속성 관련 메서드를 어떻게 사용하는지 다음의 예를 통해 알아보자.

package com.perf.timer;

import java.util.Iterator;
import java.util.Properties;
import java.util.Set;

public class GetProperties {
  public static void main(String[] args) {
    System.setProperty("JavaTuning", "Tune Lee");
    Properties prop = System.getProperties();
    Set key = prop.keySet();
    Iterator it = key.iterator();
    while(it.hasNext()) {
      String curKey = it.next().toString();
      System.out.format("%s=%s\n", curKey, prop.getProperty(curKey));
    }
  }
}

이 소스는 'JavaTuning'이라는 키를 갖는 시스템 속성에 'Tune Lee'라는 값을 지정한 후, 시스템 속성 전체 값을 화면에 출력해주는 프로그램이다. 이 프로그램을 수행하면 수십 개의 자바의 시스템 속성 값을 출력한다. 그 결과 우리가 지정한 'JavaTuning' 키를 갖고 'Tune Lee' 값을 가지는 속성이 추가되어 출력될 것이다.

• static Map<String,String> getenv()
  현재 시스템 환경 값 목록을 스트링 형태의 맵으로 리턴한다.
• static String getenv(String name)
  name에 지정된 환경 변수의 값을 얻는다.

시스템 환경 변수 관련 메서드를 사용하는 것은 자바 속성 관련 메서드를 사용하는 것과 비슷하다.

package com.perf.timer;

import java.util.Iterator;
import java.util.Map;
import java.util.Set;

public class GetEnv {
  public static void main(String[] args) {
    Map<String,String> envMap = System.getenv();
    Set key = envMap.keySet();
    Iterator it = key.iterator();
    while(it.hasNext()) {
      String curKey = it.next().toString();
      System.out.format("%s = %s\n", curKey, envMap.get(curKey));
    }
  }
}

위의 코드 수행 결과는 윈도의 커맨드 창에서 'set' 명령어를 치는 결과와 동일하다.

네이티브 라이브러리를 활용할 때 사용할 수 있는 System 클래스는 다음과 같다.

• static void load(String filename)
  파일명을 지정하여 네이티브 라이브러리를 로딩한다.
• static void loadLibrary(String libname)
  라이브러리의 이름을 지정하여 네이티브 라이브러리를 로딩한다.

그리고, 운영중인 코드에 절대로 사용해서는 안되는 메서드가 있다.

• static void gc()
  자바에서 사용하는 메모리를 명시적으로 해제하도록 GC를 수행하는 메서드이다.
• static void exit(int status)
  현재 수행중인 자바 JVM을 멈춘다.
• static void runFinalization()
  Object 객체에 있는 finalize()라는 메서드는 자동으로 호출되는데, 가비지 컬렉터가 알아서 해당 객체를 더 이상 참조할 필요가 없을 때 호출한다. 하지만 이 메서드를 호출하면 참조 해제 작업을 기다리는 모든 객체의 finalize() 메서드를 수동으로 수행해야 한다.

3. System.currentTimeMillis와 System.nanoTime

시간 관련 메서드는 다음과 같다.

• static long currentTimeMillis
  현재의 시간을 ms로 리턴한다.(1/1,000초).

currentTimeMillis() 메서드에서 리턴해 주는 결과 값은 ms(밀리초)이다. UTC라는 시간 표준 체제를 따른는데, 1970년 1월 1일부터의 시간을 long 타입으로 리턴해 준다. 따라서 호출할 때마다 다르다. 이 시간 값을 변환하면 현재 날짜를 구할 수도 있다.

package com.perf.timer;

import java.util.ArrayList;
import java.util.HashMap;

public class CompareTimer {
	public static void main(String[] args) {
		CompareTimer timer=new CompareTimer();
		for(int loop=0;loop<10;loop++) {
			timer.checkNanoTime();
			timer.checkCurrentTimeMillis();
		}
	}
	private DummyData dummy;
	public void checkNanoTime() {
		long startTime=System.nanoTime();
		dummy=timeMakeObjects();
		long endTime=System.nanoTime();
		double elapsedTime=(endTime-startTime)/1000000.0;
		System.out.println("nano="+elapsedTime);
	}
	public void checkCurrentTimeMillis() {
		long startTime=System.currentTimeMillis();
		dummy=timeMakeObjects();
		long endTime=System.currentTimeMillis();
		long elapsedTime=endTime-startTime;
		System.out.println("milli="+elapsedTime);
	}
	public DummyData timeMakeObjects() {
		HashMap<String,String> map=new HashMap<String,String>(1000000);
		ArrayList<String> list=new ArrayList<String>(1000000);
		return new DummyData(map,list);
	}
}

package com.perf.timer;

import java.util.ArrayList;
import java.util.HashMap;

public class DummyData {
	HashMap<String, String> map;
	ArrayList<String> list;

	public DummyData(HashMap<String, String> map, ArrayList<String> list) {
		this.map = map;
		this.list = list;
	}
}

• static long nanoTime()
  현재의 시간을 ns로 리턴한다(1/1,000,000,000초).

사용 중인 자바 버전이 JDK 5.0 이상이면 시간 측정용으로 만들어진 nanoTime() 메서드를 사용하는 것이 좋다. 초기에 성능이 느리게 나오는데, 그 이유는 클래스가 로딩되면서 성능 저하도 발생하고, JIT Optimizer가 작동하면서 성능 최적화도 되기 때문이라고 보면 된다.

작성된 메서드의 성능을 측정하는 여러 가지 방법이 존재한다. 위에서 살펴본 nanoTime()과 같은 메서드로 측정할 수도 잇지만, 전문 측정 라이브러리를 사용하는 것도 좋은 방법이다.

• JHM
• Caliper
• JUnitPerf
• JUnitBench
• ContiPerf

이 중에서 JMH와 Caliper를 제외한 나머지 툴들은 JUnit으로 만든 테스트 코드들을 실행하는데 사용된다. JMH(Java Microbenchmark Harness)는 JDK를 오픈 소스로 제공하는 OpenJDK에서 만든 성능 측정용 라이브러리다. 위에서 살펴본 HashMap와 ArrayList 객체 생성 속도를 JMH로 확인하는 예제 코드를 살펴보자.

package com.perf.timer;

import java.util.ArrayList;
import java.util.HashMap;
import java.util.concurrent.TimeUnit;

import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.GenerateMicroBenchmark;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;

@BenchmarkMode({ Mode.AverageTime })			// 1.
@OutputTimeUnit(TimeUnit.MILLISECONDS)			// 2.
public class CompareTimerJMH {

	@GenerateMicroBenchmark				// 3.
	public DummyData makeObjectWithSize1000000() {
		HashMap<String, String> map = new HashMap<String, String>(1000000);
		ArrayList<String> list = new ArrayList<String>(1000000);
		return new DummyData(map, list);
	}
}

1) JMH는 클래스 선언시 반드시 어노테이션을 지정할 필요는 없다. 하지만 그렇게 하면 기본 옵션으로 수행되기 때문에 평균 응답 시간을 측정하기 위해서 @BenchmarkMode로 옵션을 지정하였다.
2) @OutputTimeUnit 어노테이션을 사용하여 출력되는 시간 단위를 밀리초로 지정하였다. 기본이 밀리초이지만, 나중에 옵션을 지정하는 것을 확인하기 위해서 명시적으로 지정을 해 주었다.
3) @GenerateMicroBenchmark는 측정 대상이 되는 메서드를 선언할 때 사용한다. 해당 클래스에 메서드가 많이 있더라도 이 어노테이션을 지정하지 않으면 테스트 대상에서 제외된다.

JHM을 실행한 결과에서 가장 중요한 부분은 다음과 같다.

Run statics "makeObject":min=2.015,avg=2.089,max=2.127,stdev=0.064

min은 최소, avg는 평균, max는 최대 값을 의미한다. 그리고 stdev는 표준편차를 말한다. 그러므로 이와 같은 수치를 볼 때는 평균과 표준편차를 중심으로 보면 된다. 즉, 이 실험은 2.089ms 정도가 소요되었다고 보면 된다.

이처럼 JMH를 사용하면 일일이 케이스를 구성할 필요 없이 각 케이스별로 테스트를 수행하고 그 결과를 확인할 수 있다.

참고

• 자바 성능 튜닝 이야기