앱 시작시간 최적화 하기

FlameGraph 그리기, App 시작시간 Plotting 예시. Android 시작 시간 개선 경험

2017년에 안드로이드 앱 시작 시간 최적화를 한 경험이 있습니다. 안드로이드 개발자는 아닙니다만 같은 팀에 계시던 두 분이 전 안드로이드 팀장님이시라 묘하게도 두 분다 안드로이드 팀장님 이셨습니다. 데이터 팀에게 시작 시간 개선을 하는 작업의 일부분이 맡겨졌었어요. 어떻게 보면 시작 시간 개선도 현상태를 파악하고 데이터를 보며 어떻게 개선할지 안을 내고 실행하는 작업이라 적절하다 싶었습니다.

당시 작업이 끝나고 동료에게 발표했던 자료는 여기 있습니다. 5년 전부터 인터넷에 공개되어 있었습니다.

https://ruseel.github.io/2017-09-android-perf/

당시에 앱이 출시되고 나서 네 번째 개편을 하던 순간이었습니다. 큰 변화가 생겨서 앱 시작 시간이 그 당시로부터 한 2년쯤 된 폰에서 8초쯤 걸렸는데 그게 너무 느리다고 판단해 시작된 작업이었습니다.

읽으시는 분들이 이 글을 다 읽으신 다음에는 “프로파일러는 내부에서 어떤 작업을 하는가?” “프로파일러의 결과물을 해석할 때는 어떤 일이 벌어지는가?” 에 대해 배우실 수 있는 글이었으면 좋겠습니다.

사이트 https://poormansprofiler.org/ 가 있습니다. 번역하면 가난한 자의 프로파일러입니다. Stacktrace 여러 개를 주기적으로(밀리세컨드 단위일 수도 있고 초단위일 수도 있고) 무척 여러 개(10~100개) 수집해서 통계내고 어떤 함수가 Stacktrace 에서 자주 출연하고 있는지 파악해 병목을 추정해 주는 프로그램을 "가난한 자의 프로파일러"라 부릅니다.

"가난한 자의 프로파일러"가 샘플링 프로파일러 들의 가장 원시적인 형태이겠습니다. 2017년 당시에는 프로파일링을 안드로이드 스튜디오에서 직접 지원하지 않았고 그래서 adk 로 실행 정보를 수집한 다음에 그 파일을 특정 웹사이트에 올려주면 그 정보를 FlameGraph 로 바꿔 SVG 로 다운로드 받을 수 있었습니다. https://aflame.rhye.org 그래서 액티비티의 시작 순간부터 화면에 보일 때까지를 여러 번 데이터를 수집해서 그 사이트에 올려 주었어요 그리고 SVG 를 다운로드 받아서 열어 보았었습니다.

FlameGraph 를 보고 바로 해석할 수 있으면 좋을텐데 써 보신 분들은 무척 공감하시겠지만 시행착오가 많습니다. 처음 FlameGraph 를 해석하기 시작하면 너무 정보가 많아 혼란스럽습니다. 게다가 요새처럼 여러 스레드를 걸쳐서 일이 벌어지고 있을 때 무엇이 Wall Time 에서 시간이 오래 잡고 있는지 파악하기가 무척 헷갈립니다. 게다가 이게 저의 착각인지 측정을 6번을 해서 FlameGraph 를 그려보면 3번은 A 라는 형태로 보이는 듯 싶고 3번은 B 라는 형태로 보이는 듯 싶고 이렇게 달라지는 느낌을 받기도 했습니다. 이 정보가 정확하기는 한가 싶은 의심도 들고요.

그래서 여러 Thread 의 실행시간을 모두 합친 것을 보기도 하고, 따로 나눠서 그린 FlameGraph 를 보기도 하고 했습니다. 어떤 때는 이쪽이 오래 걸리는 것처럼 보여서 그 쪽을 찾아봤는데 고쳐봐도 별 변화가 없으면 또 다른 단서가 해보고, 이런 시행착오의 연속입니다. 그러다 하나가 효과가 있으면 아 FlameGraph 에서 정작 의미있는 해석은 이런 거였나 하는 배움이 약간은 있기도 하고요.

여튼 시행 착오를 꽤 거치면서 FlameGraph 를 해독해야 하고 같은 작업을 분명 기록한 것을 FlameGraph 로 바꿨는데 결과물이 다르게 나오는 경우도 있구나 알아두시면 좋을 것 같습니다. ¹

그래도 당시에 효과를 봤던 변경을 이야기 해보겠습니다. log4j appender 가 emulator 에서 실행할 때는 영향이 없는데 기기에서 초기화 될 때는 거의 2~3초 가 걸리고 있었습니다. 그것이 최신폰에서는 영향을 안 미치고 오래된 폰의 경우에만 그랬습니다. log4j 자체 로딩이 오래걸리는 것이 아니라 log4j appender 를 jar 파일로 넣어서 사용하게 해 두었을 때 그 jar 파일을 읽어 들이는데 시간이 걸렸다고 보고 jar 파일을 마지막 build 에서 빼보니 그 시간을 싹 줄일 수 있었습니다. 시간이 8초 정도 걸리던 디바이스에서 2~3초 가량 시작시간을 줄일 수 있는 변경이었습니다. 가장 쉽게 얻은 성과였습니다.

또 다른 변경으로 채팅창으로 진입할 때 2초 가량 시간이 걸렸는데 거기서 한 1000ms 를 잡아먹고 있는 이미지 로딩 루틴이 있었습니다. 그게 당시 기준으로도 2년 전쯤 추가된 폰에서만 그런 현상이 있었고 당시 기준으로 몇 개월 안에 출시된 좋은 폰들은 또 그런 현상이 있진 않았어요. 그래서 그 이미지 로딩 루틴을 조금 더 최적화해 주고 나니 오래된 폰에서도 그런 현상이 사라졌습니다.이미지를 합쳐서 한 번에 로딩했던가 그랬습니다.

이렇게 수정, 측정을 반복하고 있을 때, 나름 어려웠던 부분이 보통 의심되는 부분에 어느정도 희망을 가지고 수정을 하다보니 그렇게 빨라진 것이 아닌데도 빨라졌다고 착각하게 되는 일들이 있었습니다. 알고 보면은 오차에 가까운 변화인데도 빨라졌다, 혹은 느려졌다고 이유를 만들게 되고는 했습니다.

시작 시간의 데이터를 얻고 ggplot 으로 시각화 해보니 명확하게 이해할 수 있었어요. 당시 동료들한테 보여주던 그림이 위에 올린 발표자료에 딱 하나 남아있습니다. 정말 여러 가지 시도를 하게 되는데 각 시도의 git commit 마다 네 개의 기종에서 어떻게 측정되었는지 보여주던 것입니다.

기종마다 차이가 엄청 컸습니다. 0~15초 사이에 퍼져있지요. 점들이 심하게 겹쳐 찍히지 않도록 제가 jitter 를 넣어서 약간 흩어지게 뿌렸지만 왜곡을 넣지 않았어요. 시각화가 이런 착각을 줄여주기에 한 번은 배워둘만 합니다.

그래프를 보면서 파악할 수 있는 사실이 있었습니다. nexus5x 가 laptop 의 emulator 를 제외하고 가장 빨리 실행되는 기기였는데 nexus5x 가 어떤 cpu cycle 을 쓰고 있었는지에 따라서 빨리 실행되는 측정군이 있고 늦게 실행되는 측정군이 있습니다. 2개의 군으로 나뉘어서 모여 있습니다. 처음에 그래프를 그려보고 있지 않았을 때는 저렇게 cpu cycle 마다 차이가 있다는 사실을 모르고 내가 마지막으로 한 변경이 효과가 있었구나 그래서 빨라졌구나 하고 생각하고는 했습니다. 한데 그러다가 분명히 변경이 적용되었음에도 다시 느려지는 경우가 있어서 참 이상하다 생각했는데 나중에 알고 보니 nexus5x 에 cpu cycle 을 온도에 따라 조절하는 기능이 들어가 있었습니다. 여튼 저렇게 그래프로 그리는 방법도 있다고 알아 두시면 좋을 것 같습니다. 발표 장표에는 저 데이터를 어떻게 얻었는지 adk 를 실행하던 shell script 를 적어두었습니다.

가끔 당시에도 “프로파일러는 정확하지 않다” 말씀하시는 분들이 있었습니다. 지금도 그렇지만 당시에도 이렇게 대답하고는 합니다. 샘플링의 정의대로 100% 정확할 수 없지만 유용한 정보를 알려준다 라고요. 아무런 단서없이, 물증없이 추측으로 조사하는 것보다 100% 정확하지는 않지만 그래도 단서를 가지고 찾는 것이 현명하다 생각합니다. 꽤 많이 유용하다고 생각하고요.

어떻게 보면 참 흔한 조언, Trial and Error 가 필요하고 혼란스런 영역이니 조심스럽게 진행하는 것이 좋겠다 라는 정도를 말했습니다. 조금이나마 도움이 되셨으면 좋겠네요.