StopWatch 사용하기

어떤 기능을 개발했는데 예상했던 것보다 실행시간이 오래 걸리는 경우가 있다. 이 때 어떤 부분에서 시간이 많이 걸리는지 확인하기 위해서 스프링 프레임워크에서는 StopWatch를 사용할 수 있다.

간단하게 Gimlet을 만드는 방법을 로그에 남기는 프로그램을 만들었다. 각 과정에 사용되는 메소드를 컨트롤러에서 차례로 호출한다.

@GetMapping("/gimlet")
public String make(){
  prepareGlass();
  chillGlass();
  prepareShaker();
  putIce();
  putGin();
  putLimeJuice();
  putSugar();
  shake();
  pour();
  serve();
  return "ok";
}

그런데 시간이 너무 오래 걸리는 과정이 있어서 문제가 되는 부분을 찾고 싶다고 하자. 각 과정에서 현재 시간을 찾아서 로그에 남기면 되지만 이 과정을 StopWatch를 사용해 간단하게 해결할 수 있다.

@GetMapping("/gimlet")
public String make() throws InterruptedException {
  StopWatch stopWatch = new StopWatch();	//StopWatch객체 생성

  stopWatch.start("잔 준비");	//stopWatch 시작
  prepareGlass();
  stopWatch.stop();	//stopWatch 끝

  stopWatch.start("칠링");
  chillGlass();
  stopWatch.stop();

  stopWatch.start("셰이커 준비");
  prepareShaker();
  stopWatch.stop();

  stopWatch.start("얼음 넣기");
  putIce();
  stopWatch.stop();

  stopWatch.start("진 넣기");
  putGin();
  stopWatch.stop();

  stopWatch.start("라임주스 넣기");
  putLimeJuice();
  stopWatch.stop();

  stopWatch.start("설탕 넣기");
  putSugar();
  stopWatch.stop();

  stopWatch.start("셰이킹");
  shake();
  stopWatch.stop();

  stopWatch.start("잔에 따르기");
  pour();
  stopWatch.stop();

  stopWatch.start("제공하기");
  serve();
  stopWatch.stop();

  System.out.println(stopWatch.prettyPrint());	//prettyPrint 사용해서 출력
  return "ok";
}

StopWatch객체를 만든 후 측정을 시작하고 싶은 부분에서 start메소드를 호출하고 측정을 끝내는 부분에서 stop메소드를 호출하면 그 사이의 시간을 측정해준다. 이때 start 메소드의 인자로 taskName을 전달해서 각 작업들을 구분할 수 있다. 마지막으로 prettyPrint 메소드를 사용하면 결과를 보기 좋게 출력해준다.