자바(java)에서 특정 로직이 얼마나 소요되는지 체크를 하는 방법을 소개한다.








1. jdk에서 제공하는 System 클래스의 currentTimeMillis() 메소드를 이용해서 확인할 수 있다.

예제
long startTime = System.currentTimeMillis();
Thread.sleep(1000);
long estimatedTime = System.currentTimeMillis() - startTime;
System.out.println("took " + estimatedTime + " ms");

결과값은 밀리세컨드(ms)로 다음과 같다.
took 1000 ms


2. jdk에서 제공하는 System 클래스의 nanoTime() 메소드를 이용해서 확인할 수 있다. 아주 정확한 시간을 측정할 때 많이 활용한다.

예제
long time1 = System.nanoTime();
Thread.sleep(1000);
long time2 = System.nanoTime();
long timeSpent = time2 - time1;
System.out.println("took " + timeSpent + " ns");

결과값은 nano 값으로 나온다.
took 1000232514 ns

3. Common-lang의 StopWatch 클래스를 이용한다. (commons-lang 2.3)

예제
import org.apache.commons.lang.time.StopWatch;

StopWatch stopWatch = new StopWatch();
stopWatch.reset();
stopWatch.start();
Thread.sleep(2000);
stopWatch.stop();
System.out.println(stopWatch.toString());
  
stopWatch.reset();
stopWatch.start();
Thread.sleep(5000);
stopWatch.stop();
System.out.println(stopWatch.toString());
  
stopWatch.reset();
stopWatch.start();
Thread.sleep(3000);
stopWatch.stop();
System.out.println(stopWatch.toString());


start를 하기전에 반드시 reset()를 해야 한다. 그 이유는 Common-lang의 StopWatch 클래스는 내부적으로 status를 가지고 있다. 이 부분에 대해서 약간 신경써야 한다. 자세한 것은 뒤에서 다시 설명한다.

결과값은 다음과 같다.

0:00:02.000
0:00:05.000
0:00:03.000


4. Spring core lib에 있는 util성 StopWatch 클래스를 이용한다. (Spring 3.0.x)

예제
import org.springframework.util.StopWatch;

...
StopWatch stopWatch = new StopWatch("Stop Watch");
stopWatch.start("initializing");
Thread.sleep(2000);
stopWatch.stop();
System.out.println("took " + stopWatch.getLastTaskTimeMillis() + " ms");
stopWatch.start("processing");
Thread.sleep(5000);
stopWatch.stop();
System.out.println("took " + stopWatch.getLastTaskTimeMillis() + " ms");
  
stopWatch.start("finalizing");
Thread.sleep(3000);
stopWatch.stop();
System.out.println("took " + stopWatch.getLastTaskTimeMillis() + " ms");
  
System.out.println(stopWatch.toString());
System.out.println();
System.out.println(stopWatch.prettyPrint());

결과 화면
took 2000 ms
took 5000 ms
took 3001 ms
StopWatch 'Stop Watch': running time (millis) = 10001; [initializing] took 2000 = 20%; [processing] took 5000 = 50%; [finalizing] took 3001 = 30%
StopWatch 'Stop Watch': running time (millis) = 10001
-----------------------------------------
ms     %     Task name
-----------------------------------------
02000  020%  initializing
05000  050%  processing
03001  030%  finalizing


얼마나 소요되었는지, 그동안의 관련정보를 계속 모아서, Task 별로 모아 정보를 출력한다.

5. 그냥 인터넷에서 남들이 만든 StopWatch를 찾아서 copy&paste한다.

http://www.devdaily.com/blog/post/java/stopwatch-class-that-can-be-used-for-timings-benchmarks



* Commons-lang의 StopWatch와 Spring Util의 StopWatch를 간단히 비교하였다.

 

Commons-lang StopWatch 클래스

Spring util StopWatch 클래스

FQN

org.apache.commons.lang.time.StopWatch

org.springframework.util.StopWatch

메모리

경량화

Commons-lang Stopwatch보다는 메모리 조금 더 소요 (Task로 관리)

사용성

O

<OO (통계를 내주니까..)

기본 메소드

Start(), stop(), reset(), suspend(), resume()

Start(),stop()

이름(id)

X

O

Running status

Unstarted, running, stopped, suspended

 

상태가 있기 때문에 규칙이 있음

 

you cannot now call stop before start, resume before suspend or unsplit before split.

 

1. split(), suspend(), or stop() cannot be invoked twice

2. unsplit() may only be called if the watch has been split()

3. resume() may only be called if the watch has been suspend()

4. start() cannot be called twice without calling reset()

Running, not running

Split

기능 :시계에서처럼 split 기능

 

Status : Unsplit, split

 

Split(), Unsplit(), getSplitTime(), toSplitString()

X

Start task name

X

O

Print

O

toString()

O

toString()

shortSummary()

prettyPrint

누적시간을 기준으로 출력

Keeping track

X

O

setKeepTaskList(boolean keepTaskList)

디폴트값은 true

isRunning

X

O

isRunning()

Last time

X

O

getLastTaskTimeMillis()

Total time

X

O

getTotalTimeSeconds()

getTotalTimeMillis()

Task count

X

O

getTaskCount()






추가 - guava stopwatch 


예제

import java.util.concurrent.TimeUnit;

import org.junit.Test;

import com.google.common.base.Stopwatch;

public class GuavaTest {

@Test
public void test() {

Stopwatch 
stopwatch = Stopwatch.createStarted();

try {
Thread.sleep(1000);
catch (InterruptedException e) {
e.printStackTrace();
}

System.
out.println("Elapsed time : " + stopwatch);
System.
out.println("Elapsed time (milliseconds) : " + stopwatch.elapsed(TimeUnit.MILLISECONDS));
System.
out.println("Elapsed time (microseconds) : " + stopwatch.elapsed(TimeUnit.MICROSECONDS));
System.
out.println("Elapsed time (nanoseconds) : " + stopwatch.elapsed(TimeUnit.NANOSECONDS));
                
                                stopwatch.stop();
}



결과

Elapsed time : 1.001 s

Elapsed time (nanoseconds) : 1004995000

Elapsed time (microseconds) : 1005043

Elapsed time (Milliseconds) : 1005


'general java' 카테고리의 다른 글

구글 프로토콜 버퍼 (Google Protocl Buffer)  (0) 2011.08.03
Hiberate 4  (0) 2011.07.15
DBCP connection 정리  (0) 2011.07.05
Spring Batch - MSSQL 채번  (0) 2011.04.07
Spring Batch retry 예제들  (0) 2011.04.06
Posted by '김용환'
,