[펌]Android Traceview War Story

출처 : http://blog.naver.com/PostView.nhn?blogId=huewu&logNo=110095622035&parentCategoryNo=18&viewDate=&currentPage=1&listtype=0
 
Android Traceview War Story

원문: http://android-developers.blogspot.com/2010/10/traceview-war-story.html

[이 포스트는 Tim Bray 에 의해 작성되었습니다.]

 Tim Bray 는 안드로이드 개발자 블로그의 운영자로, 실재 안드로이드 개발팀의 여러 엔지니어가 작성한 내용을 바탕으로 블로그 포스팅을 해왔습니다만, 오랜만에 자신이 직접 작성한, Trace View 사용법에 관한 블로그 포스트를 업데이트 하였네요. 유용한 내용이기도 하고, 왠지 반가운 기분에 한번 번역해 보았습니다.

 최근에 Traceview 기능에 대해 진지하게 살펴보았습니다. 몇 가지 생각이 머리에 스치더군요. 첫째로, Traceview 기능을 한번도 사용해보지 않은 안드로이드 개발자들이 몇몇 정도는 있을거라는 생각과, 또 한가지 제가 가장 좋아하는 주제 중 하나인 성능 개선과 프로파일링에 관련된 진지한 포스트를 작성할 수 있는 기회라는 생각이 들었습니다. 이번 포스트는 "안드로이드 기초 수업" 이라고 할만한 기본적인 내용이 될 것입니다. 만일 여러분이 Traceview 에 관해 이미 알고 계신다면, 여기까지만 읽으셔도 될 듯 하네요.

어플리케이션이 빠르게 동작하도록 만들기

 어플리케이션이 조금만 보잡해져도 여러분은 해당 어플리케이션의 어느 부분이 속도를 느리게 만드는지 예상할 수 없습니다. 왜냐하면 그 누구도 소프트웨어에서 병목 현상을 일으키는 부분이 어떤 곳이라고 콕 찝어낼만큼 똑똑할 수 없기 때문입니다. 최소한 저랑 제 주변에 있는 경험 많은 대부분의 개발자들은 그렇게 믿고있습니다.

 따라서 빠르게 동작하는 어플리케이션을 작성하기 위한 가장 현명한 방법은 어플리케이션을 최대한 단순하게 작성하는 것 입니다. 여러분이 N승 형태로 연산량이 증가되는 바보같은 알고리즘을 사용하거나 안드로이드 UI 상에서 I/O 작업을 수행하는 등의 명백한 실수만 하지 않는다면, 혹시 모르지요. 작성한 어플리케이션이 만족할 만큼 빠르게 작동할 수도 있습니다.

 하지만 만일, 작성한 어플리케이션이 충분히 빠르지 않다면, 왜 그럴까? 하고 추측하거나 고민하지 마세요. 대신, 프로파일러를 사용하여 해당 현상을 측정하고 원인을 분석할 수 있습니다. 예전같으면, System.err.println("Entered at" + System.currentTimeMillis()); 같은 구문을 사용해서 그런 작업을 수행하곤 했습니다. 하지만 다행히 안드로이드에서는 훌륭한 프로파일러를 지원하고 있기 때문에, 이렇게 지저분한 코드는 사용하지 않으셔도 좋습니다.

사례 연구: LifeSaver 2

 저는 얼마전에 안드로이드 마켓에 LifeSaver 2 라고 하는 간단한 유틸리티 어플리케이션을 배포하였습니다. 이 어플에 관한 자세한 내용은 개인 블로그  의 포스트를 참고해 주세요. 이 어플은 안드로이드 폰의 SMS 와 전화 콜 로그를 추출하여 이를 JSON 텍스트 파일 형식으로 SD 카드에 저장해 두는 기능을 갖고 있습니다. 이 작업에 어느정도 시간이 걸리는 작업이기 때문에 멋드러진 프로그레스 바를 표시하도록 하였습니다. 그런데 엄청나게 빠른 기가헤르츠 단위의 프로세서를 갖춘 휴대폰에서, 고작해야 몇백줄의 리코드를 텍스트 파일로 디바이스에 저장하는데 왜 긴 시간이 걸리는지 의문이 들더군요.

 구지 제 충고를 무시하는 분들은 이러한 성능 저하가 ContentProvider 의 Cursor 가 시스템 로그를 읽는 시간때문이라던가, 그게 아니면 SD 카드에 내용을 쓰는데 발생하는 오버헤드라고 지례 짐작 하실 수도 있습니다. 대신에, 우리 스마트한 사람들은 프로파일러를 이용하여 코드를 계측하고 원인을 파악해 냅니다. 한번 해 봅시다.

Trace 시작하기

Saver.java 파일을 열어 run() 메서드 내의 코드를 아래와 같이 묶어 줍니다.

       public void run() {


            android.os.Debug.startMethodTracing("lsd");


            // ... method body elided


            android.os.Debug.stopMethodTracing();

        }

 첫 번째 문장은 Trace 기능을 작동 시키며, 인자로 사용된 "lsd" (Life Saver Debug 의 약자입니다.) 는 "/sdcard/lsd.trace" 경로에 Trace 로그 정보를 저장하라는 뜻입니다. 주의할 점 한가지. SD 카드에 로그 파일을 저장함으로 WRITE_EXTERNAL_STORAGE 권한을 설정해 두어야 합니다. 실제로 어플리케이션을 릴리즈 할 때는 물론 이 권한 항목을 제거해 두어야 겠지요. 

[업데이트] 안드로이드 개발자 Xavier Ducrohet 는 저에게 "DDMS" 의 "Device View" 에 프로파일을 시작/정지 시킬 수 있는 버튼이 있다는 것을 알려주었습니다. '정지' 버튼을 누르면 생성된 Trace 로그 파일을 기반으로 TraceView 가 실행됩니다. 이 방법이 여러분의 코드에 start/stopMethodTracing 을 직접 넣는 것 처럼 정교한 측정 작업을 사용하는데는 부족함이 있지만, 알아두면 굉장히 유용한 팁이 될 것입니다. 또한, 프로파일링 작업을 위하여 프로요 이전 버전에서는 WRITE_EXTERNAL_STORAGE 권한이 반드시 필요하지만 그 이 후 버전에는 VM 이 Trace 파일을 JDWP 커넥션을 이용하여 SD 카드에 Trace 파일을 전달함으로 권한을 설정할 필요가 없다고 합니다.(와우! 고마워요 Xav!)

그럼 여러분의 어플리케이션을 실행 한 후, Trace 로그 파일을 컴퓨터로 옮겨 TraceView 를 실행 시켜 봅시다.

540> adb pull /sdcard/lsd.trace

541> traceview lsd

 이 시점에서, 여러분은 세 가지를 확인할 수 있습니다. 첫째로, Trace 기능을 실행하면 어플리케이션 실행 속도가 굉장히 느려집니다. 두 번째, Trace 로그 파일은 굉장히 큽니다. 약 4초 정도 돌렸더니 8.6MB 가 되는 군요. 마지막으로 TraceView 는 꽤나 멋지게 생겼습니다.

<그림을 클릭하시면 확대됩니다.> 

 최상단의 바는 어플리케이션에 동작하고 있는 스레드와 각각이 어느 정도의 시간을 소비하고 있는지 알려줍니다. 넥서스 원은 단일 스레드 CPU 이기 때문에 각각의 스레드는 서로 돌아가며 동작합니다. 

<그림을 클릭하시면 확대됩니다.> 

 첫번째 스레드는 우리가 작성한 어플리케이션 코드가 동작하고 있는 부분이고 (붉은 부분은 GC 가 일어난 부분입니다.) 가운데 줄은 UI 스레드가 동작하고 있는 내용이며 프로그레스 바가 업데이트 될 때마다 일정 작업을 수행하고 있습니다. 그리고 마지막 세 번째 HeapWorker 는 정확히 무슨일을 하는지 저는 잘 모르겠습니다만, (주> GC 가 일어날 때, 해당 객체들이 사라지기 전에 Finalize 작업을 수행해주는 스레드입니다. 다음 포스트를 참고해 주세요.) 성능상에 별다른 영향을 주는 거 같지 않군요. 무시하도록 하겠습니다.

 화면 아래쪽에 표시된 내용들은 좀 더 흥미로운 정보를 담고 있습니다.어떤 메서드가 얼마나 많은 시간을 소비하는지 표시해 주며, 여러가지 다양한 방식으로 정렬할 수 있습니다. 처음 두 줄을 한번 살펴봅시다.

<그림을 클릭하시면 확대됩니다.> 

 처음 두 줄은 다음과 같은 의미를 갖습니다. 최상위 루틴에서 일어나는 모든 일을 다 합칠 경우 100% 의 시간을 소비합니다. (뭐, 당연하지요.) 하지만, 루틴 내부적으로 호출되는 메서드를 제외하고, 자기 자신만 따져보면 오직 0.9% 의 시간만을 소비합니다. 다음 라인에는 정말로 재미있는 정보가 담겨있습니다. java.io.PrintStream.printIn(Object) 메서드와 이 메서드가 포함하는 다른 메서드들을 합치면 65.2% 의 시간이 소비됩니다. 이 메서드가 JSON 객체를 SD 카드에 사용됩니다. 따라서 우리는 휴대폰의 ContentProvider 에서 데이터를 꺼내는 부분은 별다른 문제가 되지 않으며, 그 결과를 출력하는 부분이 바로 문제의 원인임을 알 수 있습니다.

 하지만 우리가 이 문제가 바로 SD 카드의 읽기 성능 때문에 발생하는 문제라고 결론 내릴 수 있을까요? 좀 더 상세하게 살펴봅시다. 해당 라인을 클릭하면 보다 자세한 내용이 나타납니다.

<그림을 클릭하시면 확대됩니다.> 

 이런, 놀랍군요. println 메서드는 내부적으로 전달 받은 인자를 String 으로 변환하기 위해 toString() 메서드를 호출 하게 되는데, 이 과정에서 약 50% 정도의 시간이, 그리고 실재로 정보를 출력하기 위한 println(String) 메서드에서 나머지 50% 정도의 시간이 소비됩니다. println(String) 메서드는 더 자세히 살펴볼 필요가 없을거 같네요. SD 카드에 데이터를 쓰기 위해 어느 정도의 시간이 소비 되는 것은 틀림없어 보입니다. 하지만 String.valueOf() 가 호출 될 때는 무슨일이 벌어지는 것 일까요?

<그림을 클릭하시면 확대됩니다.> 

 드디어 진실이 밝혀졌습니다. org.json.JSONObject.toString() 이 문제의 원인이였군요. 그런데 이 메서드는 우리 전문 프로그래머들이, 어... 이 함수는 내가 작성한 것이 아니라, 사용하고 있는 라이브러리에서 제공해주는 메서드이기 때문에 왠만하면 건들고 싶지 않아... 라고 이야기하는 종류의 메서드입니다. (주> 번역이 어렵네요. 원문은 what we professional programmers call a, well, this is a family-friendly operation so I won’t go there. 인데, 뭐라고 해석하면 좋을까요?) 여러분은 이 메서드의 내부를 좀 더 살펴볼 수는 있겠지만 별다른 소득을 얻을 수는 없을 것 입니다.

 대신에 여러분은 각각의 루틴들이 독점적으로 사용하는 시간을 기준으로 프로파일링 결과를 재정렬 해볼 수 있습니다. 아래의 목록은 1% 이상의 CPU 시간을 소비한 루틴들의 목록입니다.

<그림을 클릭하시면 확대됩니다.> 

 GC 관련 작업이나, 안드로이드 프레임워크에서 View 를 그리는 작업과 관련된 것들이 몇몇 눈에 띄기는 하지만, 무엇보다도 org.jason 과 java.lang.StringBuilder 코드 부분에서 가장 큰 시간이 소요됨을 확인 할 수 있습니다.

결론

 이번에 수행한 어플리케이션 프로파일에 관련된 진짜 결론은, 사실 성능 문제에 관하여 별다른 신경을 쓸 필요가 없다는 점 입니다. (뭥미-_-). 위에서 테스트한 루틴은 실재 어플리케이션 상에서 오직 두 번 (옛날 휴대폰에서 한 번, 새로운 휴대폰에서 한 번)만 수행되며, 성능상의 문제는 별로 발생하지 않지요.

 하지만, 만일 제가 위 구문의 성능을 개선시키고자 한다면 어떤 방법을 활용할 수 있을까요? 첫째, JSON 을 사용하지 않거나 JSON 객체를 좀 더 효율적으로 시리얼라이즈 할 수 있는 방법을 찾을 것입니다. 두번째로, println() 메서드의 사용을 최소화 하여 출력하고자 하는 데이타를 하나의 큰 버퍼에 꾸역 꾸역 밀어 넣은 후에, 단 한 번의 I/O 호출로 단번에 SD 카드에 기록하도록 코드를 수정하겠지요.

 여기서 중요한 점은, 만일 제가 이 루틴에서 발생하는 병목현상이 어디서 일어나는지 추측하고자 했다면 아마도 저는 결코 그 원인을 올바르게 짚어내지 못했을 것이라는 점입니다. Traceview 는 훌륭한 툴입니다. 그리고 만일 여러분이 Traceview 에 대해 잘 모르고 있었다면, 꼭 한 번 사용해 보시기 바랍니다.

[출처] [번역] 안드로이드 Trace View 기능을 활용하기|작성자 휴우