[안드로이드 삽질기록] Line by Line으로 코드의 실행속도를 측정하고 싶을 때

사건의 발단

지난 달, openCV를 활용해 이미지처리 기능을 구현하고 있었다.

이미지처리 과정이 상당히 복잡해서, Core 연산이 아주 많이 들어갔다.

메서드 여러 개로 나누어서 작업하고 있는데도 한 메서드가 몇백 줄이 넘어가는 길이였다.

 

연산이 복잡하기 때문에 어떤 줄에서 초 단위로 느려지는지 눈으로 확인하고 싶었다.

안드로이드 스튜디오의 프로파일러를 활용하면 큰 틀에서의 네트워크나 메서드 단위는 확인할 수 있지만,

한 줄 한 줄의 실행속도를 측정하는 것은 어려워 보였다.

 

삽질의 과정

그래서 직접 코드로 실행 시간을 확인하기로 했다.

 

처음에는 일반 예제에서 많이 하듯이 System.currentTimeMillis()만을 활용해 보려고 시도했다.

prevTime과 curTime이라는 Long타입의 변수들을 생성해 주고,

원하는 위치에서 이 두 값을 갱신해 주면서 (curTime - prevTime)을 로그로 찍어서 시간 변화를 확인했다.

 

하지만 문제가 있었다.

코드가 못생긴 것은 둘째 치고, 로그를 찍는 위치가 많아지면서 이 로그가 어디서 찍힌 건지 알기 어려워졌다.

어딘가에서 1초 이상의 시간이 걸린다는 로그가 찍히긴 했는데 그게 어디인지를 모르겠는 것이다.

 

그래서 현재 어느 라인을 보고 있는지 확인하는 코드를 추가했다.

Thread.currentThread().stackTrace[3].lineNumber를 활용한 메서드로 현재 line을 출력할 수 있었다.

(이때 stackTrace[] 안의 값은 stackTrace기준으로 밑에서 몇 번째 depth에 해당하는 line을 볼 것인가이다.

나는 메서드 안에 이 코드를 추가했기 때문에 3이지만 본문 내에서 직접 line을 확인하려면 2를 넣으면 된다.)

 

이렇게 현재 line과 이전 로깅으로부터 흐른 시간을 출력할 수는 있었지만 마음에 들지 않았다.

일단 코드가 너무 못생겼었고(특히 startTime, prevTime의 활용이), 재사용성이 떨어졌다.

나중에 다른 프로젝트에서 혹시라도 다시 가져다 쓸 일이 있다면 불편할 것 같았다.

 

그래서 이 기능을 수행하는 util 클래스를 새로 만들기로 했다.

 

삽질의 결과

편안하게 라인 디버깅을 하기 위해서,

util패키지 내에 LineDebugger.kt라는 새로운 클래스를 작성했다.

 

클래스 내에는 두 메서드가 있다. privavte으로 지정된 getLineNumber()와 public인 timeFactorTest().

getLineNumber()는 stackTrace를 이용해서 timeFactorTest()가 호출된 라인 넘버를 알려주는 역할을 한다.

timeFactorTest()는 클래스 내에서 prevTime, curTime을 자동으로 변경해 주고 라인 단위 시간에 대해 로깅한다.

import android.util.Log
class LineDebugger(startTime: Long) {
    var prevTime = startTime // initialize

    private fun getLineNumber(): Int = Thread.currentThread().stackTrace[4].lineNumber

    fun timeFactorTest() { // for debugging
        val curTime = System.currentTimeMillis()
        Log.d("LINE CHECKING", "time elapsed until line: " + getLineNumber() + ": " + (curTime - prevTime))
        prevTime = curTime
    }
}

유틸 클래스를 하나 만들어두고 나니 로깅이 확연하게 간단해졌다.

우선 라인디버깅을 사용할 액티비티에서 시작 시간을 파라미터로 넣어서 이 클래스를 생성한다.

private var lineDebugger = LineDebugger(System.currentTimeMillis())

그리고 원하는 위치에서 아래처럼 lineDebugger.timeFactorTest()를 호출하면,

직전에 이 함수가 호출된 시각(또는 처음 시간)을 기준으로 몇 ms가 흘렀는지를 현재 line number와 함께 로깅해준다.

lineDebugger.timeFactorTest()

 

라인디버깅 삽질일기 끝!