[안드로이드] 메소드 프로파일링(profiling or tracing)

메소드 프로파일링을 통해 애플리케이션이 실행되는 동안 어떤 쓰레드의 어떤 메소드가 얼마나 오래 수행되었는지 알 수 있습니다. 

(안드로이드에서는 profiling을 tracing이라고도 부르더군요)

Trace 파일 생성

1. 코딩을 통한 생성

Debug 클래스의 startMethodTracing("trace-base-name") 메소드와 stopMethodTracing() 메소드를 통해 프로파일링을 시작/종료할 수 있습니다. 보통 activity의 onCreate()에 Debug.startMethodTracing("trace-base-name"); 를 넣고, onDestroy()에 Debug.stopMethodTracing();를 넣어 액티비티가 생성되고 소멸되는 동안 프로파일링을 수행하게 합니다.

프로파일링이 끝나면 /sdcard/<trace-base-name>.trace 파일이 생성됩니다. (반드시 sdcard가 있어야하며 애플리케이션이WRITE_EXTERNAL_STORAGE 퍼미션을 가져야합니다)

2. DDMS에서 생성

DDMS에서 프로세스 선택후 "Start Method Profiling" 메뉴를 선택하면 프로파일링이 시작됩니다. 다시 메뉴를 선택하면 프로파일링이 종료됩니다.

프로파일링이 끝나면 /sdcard/<패키지명>.trace 파일이 생성되면서 자동으로 TraceView가 실행됩니다.

3. shell에서 생성

adb shell로 진입해서 am profile 명령어로 특정 프로세스에 대해 프로파일링할 수 있습니다.

$ adb shell

# am profile <PPRCESS ID> start <TRACE FILE> (프로파일링 시작)

# am profile <PPRCESS ID> stop (프로파이링 종료)

예를 들면,

# am profile 16434 start /sdcard/myprofile.trace

(이제 애플리케이션에서 문제가 되는 기능을 사용해본다)

# am profile 16434 stop

4. 에뮬레이터 시작옵션

에뮬레이터를 사용한다면 에뮬레이터 시작시 emulator.exe -trace <name> 옵션을 준 후, 에뮬에서 F9 누르면 트레이싱이 시작되고 다시 F9 누르면 트레이싱이 종료됩니다. 이 경우 패키지 관계없이 전체가 프로파일링 됩니다(native tracing).

트레이싱이 끝나면 C:\Documents and Settings\Administrator\.android\avd\AVD이름.avd\traces\<name> 폴더에 qtrace.* 형태의 여러 파일들이 생성됩니다. 그러나 이들 파일은 테스트해 본 바로는 현재 TraceView로 분석 불가합니다.

Trace 파일 분석

1. TraceView

trace 파일은 SDK에 포함된 traceview 툴을 이용하여 그래픽컬하게 분석할 수 있습니다.

$traceview <trace파일의 절대경로> (단, .trace 확장자 제외)

예를들어 trace파일이 C:/myapp.trace 이면 $ traceview C:/myapp

traceview 분석화면은 timeline 패널과 profile 패널로 나뉩니다.

2. Timeline 패널 

timeline 패널은 각 쓰레드별로 메소드가 언제 시작/종료됐는지 색상으로 표시합니다. 주로 main 쓰레드에서 대부분 일이 처리되고 있음을 알 수 있습니다.(마우스를 드래그하여 구간을 선택하면 확대됩니다)

3. Profile 패널 

profile 패널은 메소드 내부 상세 수행시간을 표시합니다.

profile 패널의 각 컬럼의 대략적인 의미는 다음과 같습니다.

• Name : 클래스의 메소드명, 맨 앞의 숫자는 메소드 호출 순서(call reference)
• Inclusive : 해당 메소드 및 그것이 호출하는 메소드(자식메소드)를 포함한 수행시간.
• Exclusive : 해당 메소드 자체 순수 수행시간(메소드는 여러번 수행될 수 있으며 이들을 모두 합친것임)
• Calls : 전체 tracing 기록 중에서 몇번 호출되었는지.
• Recur Calls : recursive call이 몇 번인지(?)
• Time/Call : 해당 메소드 1번 호출 당 수행시간.

각 컬럼을 클릭하면 해당 컬럼 기준으로 정렬하여 볼 수 있습니다. 

또한 각 메소드를 선택하면 가지가 펼쳐지면서 Parents와 Children이 나타납니다.

• Parents : 해당 메소드를 호출한 놈. caller
• Children : 해당 메소드가 호출한 놈. callee

Children에서 self는 다른 메소드를 호출하지 않는 순수 자체 코드가 점유한 시간을 의미합니다.

분석 요령

profile 패널을 통해서 어떤 메소드가 애플리케이션 수행시간을 다 까먹고 있는지, 어떤 메소드가 많이 호출되었는지 등의 중요한 정보를 구할 수 있습니다. 

먼저 "Incl% 컬럼"을 기준으로 수행시간 점유비율이 뚝 떨어지는 곳들을 찾습니다. 아래 그림에서는 1번과 2번 메소드의 차이가 대략 30% 포인트 차이가 납니다. 1번 메소드를 펼쳐 Children을 봅니다. Children 중에서 2번과 10번이 대부분의 시간을 차지하는 것을 알 수 있습니다.(Chilren에서 Incl% 값은 현재 펼쳐진 메소드에 국한된 상대 비율입니다). 2번(또는 10번)을 선택하여 그 2번 메소드는 또 어떤 Child가 대부분의 수행시간을 차지하고 있는지 들어갑니다. 이런 식으로 퍼센티지가 높은 Child 위주로 계속해서 파고들다보면 근본적으로 어떤 메소드에서 쓸데없이 많은 시간을 까먹고 있는지 찾아낼 수 있습니다.

나머지 Excl% 컬럼, Calls 컬럼, Time/Call 컬럼을 기준으로 정렬하여 특별히 Exclusive 비율이 높은 메소드. Call 횟수가 너무 많은 메소드, 한번 호출시 수행시간이 오래 걸리는 메소드 위주로 분석하면 됩니다.

* 내용추가 (2010-11-15)

timeline 패널을 통해서는 쓰레드별로 작업을 분담해서 처리하는 모습을 한눈에 파악할 수 있습니다. 어느 쓰레드가 대부분의 작업시간을 점유하는지를 금방 알 수 있고, 한 쓰레드에서 다른 쓰레드로 작업이 전이되는 모습을 볼 수도 있으며, 반복적인 패턴 등 우리에게 영감을 주는 패턴을 발견할 수도 있습니다.

아래의 예제는 "AsyncTask : 어떤 작업수행 -> AsyncQueryWorker : 목록조회 쿼리 실행 -> main : 화면다시그리기" 작업이 반복되는 패턴을 보여줍니다. 실제로 AsyncTask에서 핵심적인 작업을 처리하는 시간보다, 그 결과를 UI에 곧바로 반영하기 위해 쿼리를 다시 날리고 main 쓰레드에서 화면 갱신하는데 대부분의 시간을 까먹고 있는 것을 알 수 있습니다. 이 경우 AsyncTask에서의 작업이 모두 완료될 때까지 쿼리실행을 막는 것으로 성능을 개선할 수 있었습니다.

* 안드로이드 프로파일링에 대한 좀더 심층적인 자료는 아래 링크를 참조하세요.

http://www.kandroid.org/board/board.php?board=qawithgoogle&command=body&no=22