Instruments를 활용한 행 분석하기

안녕하세요. 그린입니다 🍏
이번 포스팅에서는 Instruments를 활용해 행을 분석해보는것에 대해 자세히 알아보려 합니다 🙋🏻

 

저번 행 추적하기 포스팅을 통해 WWDC22를 보면서 행이 어떤것이고 각 개발 단계에서 어떻게 추적할 수 있는지 알아봤습니다.

 

행 추적하기

 

이번에는 거기서 한번 더 나아가 WWDC23에서 소개된 Analyze hangs with Instruements 세션을 보면서 이제는 행을 어떻게 분석하는지를 좀 더 자세히 보겠습니다!

 

---

Analyze hangs with Instruments

---

What is a hang?

행에 대해서 좀 더 자세히 어떤것인지 먼저 짚고 넘어가봅니다.

 

WWDC 세션에서는 행을 더 잘 이해할 수 있도록 실제 상황에 접목시켜 설명하고 있습니다.

 

 

이렇게 예시로 대화하는것에서도 1초의 딜레이가 발생할 수 있죠.

그런데 어색하거나 딜레이가 있다고 느껴지지 않잖아요?

 

그런데, 아래와 같이 전구에 케이블을 꽂아 전기를 공급하면 1초의 딜레이는 정상적이라고 느껴지지 않을거에요.

 

 

즉각적인 반응을 기대하니까요 😃

 

같은 딜레이가 걸리더라도 상황에 따라 느껴지는게 다르다는걸 말하고 있습니다.

물론 이 딜레이 수치도 당연히 사람마다 다릅니다.

 

그래서 일반적으로 행은 걸리는건데, 이 행이 얼마나의 수치 이하로 걸려야 사람들이 자연스럽게 느끼냐가 중요합니다.

 

 

이렇게 전구에 딜레이가 걸릴때 100ms가 임계값으로 대략 100ms 이하로 딜레이가 걸리면 실제 딜레이라고 인식할 수 없습니다.

250ms면 이제 딜레이가 눈에 띄게 됩니다.

 

이러한 수치를 행에서 임계값들을 정해봤어요.

 

 

 

버튼을 누르는것과 같은 개별 상호작용에 대해서는 대략적으로 100ms 미만의 딜레이가 일반적으론 즉각적이다라고 느껴집니다.

250ms까지도 상황에 따라 다르지만, 문제가 없다고 느껴질 수도 있어요.

그러나 그보다 길게 딜레이가 잡히면 무의식적으로 끊긴다 느낌이 들 수 있습니다.

그렇기에, 대부분의 툴에선 기본적으로 250ms부터 비정상적인 행으로 보아 행을 기록하지만 사실 무시하기 쉽기 때문에 마이크로 행이라고 부릅니다.

500ms부턴 확실히 즉각적으로 느껴지지 않기에 행으로 분류되죠.

 

그렇기에 즉각적인 느낌을 원한다면 100ms 이하로 잡는것이 가장 이상적입니다 ☺️

네트워킹과 같은 요청-응답의 상호 작용이 있는 경우엔 500ms까진 괜찮을 수 있어요.

 

정리하자면, 이 수치들은 정답이 아닌 표준적인 임계값으로 보는것이 좋고 각 앱의 상황에 따라 같은 값이라도 즉각적이거나 덜 즉각적으로 느껴질 수 있습니다.

 

이번 포스팅에서는 우리는 UI 요소가 정말 즉각적으로 느껴지는 100ms를 목표로 다뤄볼거에요!

 

---

Event handling and rendering loop

행이 발생하는 방식을 이해하는데 기초가 되는 이벤트 처리 및 렌더링 루프에 대해서도 먼저 짚어 봅니다.

 

UI 요소가 즉각적으로 반응할 수 있도록 하려면 메인 스레드를 UI 이외의 작업으로부터 자유롭게 해주는것이 중요하죠.

그걸 위해서 우리는 애플 플랫폼에서 이벤트 처리 방식과 화면 업데이트 방식을 살펴보려 합니다.

 

 

사용자의 인터랙션에 의해 하드웨어가 운영체제에 전달되고, 운영체제는 프로세스에서 이벤트를 처리하도록 전달하죠.

여기서 이벤트를 처리하는것은 앱의 메인 스레드의 역할입니다.

UI 업데이트를 결정하죠.

 

이 UI 업데이트는 개별 UI 레이어를 합성해 다음 프레임을 렌더링하는 별도의 프로세스인 렌더 서버로 전송됩니다.

 

마지막으로 디스플레이 드라이버는 렌더 서버에서 준비한 비트맵을 선택하고 이에 따라서 화면의 픽셀을 업데이트합니다.

 

이 과정에 대해 더 자세한 동작 원리를 알고 싶다면, Improving app responsiveness 문서를 보면 좋습니다.

 

Improving app responsiveness | Apple Developer Documentation

 

이어서, 해당 시간에 다른 이벤트가 들어오면 병렬로 처리될 수 있습니다.

 

 

메인 스레드 도달전 이벤트 처리 단계와 이후의 렌더링 및 업데이트 단계는 일반적으로 딜레이 시간 예측이 가능합니다.

대부분 상호 작용에서 딜레이가 많이 발생하는건 거의 메인 스레드 해당 부분이 오래 잡아먹거나 메인 스레드에서 다른 작업이 실행중이기에 그렇습니다.

 

즉, 이상적으론 메인 스레드에서 100ms 이상 소요되는 작업이 없어야하겠죠? 😄

 

이제 다양한 행을 일으키는 케이스에 따라 어떻게 해결하는지 알아보겠습니다 🙋🏻

 

---

Busy main thread hang

이제 Instruments를 활용해 앱을 프로파일링 해봅니다.

여기서 우리는 Time Profiler를 선택해 진행합니다.

 

 

이제 앱이 실행되면 앱을 자유롭게 사용하며 측정을 합니다.

 

 

좌측 상단 녹화 버튼으로 측정을 시작하고 중단할 수 있어요.

현재는 측정이 완료된 상태이고 Hangs 부분에 보면 심각한 행이 발생했음을 보여주고 있습니다.

 

메인 스레드 문제는 크게 두가지로 구분해볼 수 있습니다.

 

 

하나는 여전히 메인 스레드에서 이전 작업이 수행되고 있는 Busy Main Thread의 경우입니다.

이 케이스엔 메인 스레드에서 많은 CPU 활동이 표시되죠.

 

다른 하나는 메인 스레드가 차단된 경우에요.

일반적으로 다른 작업이 다른 스레드에서 완료되기를 메인 스레드가 기다리고 있는것입니다.

스레드가 차단되면 메인 스레드의 CPU 활동이 거의 존재하지 않습니다.

 

두 케이스에 따라 수정 방법이 다르기에 먼저 어떤 케이스에 우리가 해당하는지 확인해봐야 합니다.

 

그럼 메인 스레드부터 찾아봐야겠죠?

 

 

행 섹션 밑에 프로세스를 열어보면 스레드들이 나타납니다.

현재 비 정상적인 행 발생 시, CPU 사용량이 크게 많은걸 볼 수 있죠.

우리는 현재 원인이 Busy Main Thread 케이스에 해당함을 알 수 있습니다.

 

 

이렇게 추가로 하단에 해당 메인 스레드에서 실행된 모든 콜 트리 등도 보여줍니다.

 

행에서 발생한 일에만 집중해보기 위해 타임라인에서 행 부분을 더블 탭하여 Set Inspection Range를 통해 좀 더 확대해 봅니다.

 

 

그럼 아래와 같이 해당 행 간격 범위가 확대되고 세부 정보 보기에 표시된 데이터가 선택한 시간 범위로 필터링 됩니다.

 

 

이렇게 높은 CPU 작업이 이제 대체 뭐였는지 알아봐야겠죠?

 

하단 콜 트리에서 우측에 Heaviest Stack Trace에서 어떤것이 대부분 많이 잡아먹는지 요약된것이 있습니다.

 

 

해당 항목을 선택해 더 자세히 어떤 콜 스택으로 되어있는지 확인할 수도 있습니다.

 

해당 정보를 보니 행은 뷰의 body가 무거워서 그런것 같다고 판단됩니다.

 

Busy Main Thread에도 두가지 케이스가 있어요.

 

 

메서드 자체가 오랫동안 실행되는 경우와 단순히 여러번 자주 호출된 경우

 

 

이렇게 두가지 경우겠죠?

 

좌측은 최하단 호출되는 여러 함수를 살펴보는게 유리하지만,

우측의 경우엔 해당 함수를 호출하는 대상이 뭔지를 파악하고 덜 자주 호출할 수 있도록 수정하는것이 유리합니다.

즉, 좌측은 아래로 확인해보면 좋고 우측은 위로 확인해보면 좋습니다.

 

Time Profiler가 어떤 케이스인지까지 알려주지 않아요.

두 케이스 모두 발생할 수도 있죠.

 

만약 특정 함수의 실행 시간을 측정하려면 os_signposts를 활용하는것도 좋습니다.

 

Instruments에서 파악하기 위한 추가 도구로 SwiftUI View Body를 활용하는것도 방법입니다.

 

 

해당 항목을 드래그하여 타임라인에 놓습니다.

이제 다시 측정해봅니다!

 

 

행이 걸린곳에서 뷰를 확인해보니, BackgroundThumbnailView로 표시된 간격이 많죠?

주황색은 특정 바디 실행의 런타임이 SwiftUI에서 목표로 하는것보다 더 오래 걸렸음을 나타냅니다.

더 큰 문제는 너무 자주 이 항목이 많다는거에요.

 

하단 Timing Summary 탭을 보면 더 자세히 얼마나 카운트되었고 시간을 소요했는지 볼 수 있습니다.

 

 

여기서 BackgroundThumbnailView의 body가 70번 실행되고 총 딜레이 시간이 3초가 넘는걸 볼 수 있습니다.

 

우린 이게 원인이란걸 이제 더 구체적으로 알았습니다.

 

즉, 6개의 이미지만 표시해야하는데 70개 모든 이미지의 백그라운드를 가지고 그리고 표시하고 있는것이죠.

 

 

코드 수정을 위해 이제 Xcode에서 해당하는 부분으로 가야 합니다.

 

 

메인 스레드에서 우클릭하여 Reveal in Xcode를 통해 해당 코드까지 이동할 수 있습니다.

 

 

코드를 보면 백그라운드 뷰가 이렇게 반복되고 있네요.

코드를 보면 화면에서 당장 보여지지 않더라도 일단 다 그리고 보는 코드입니다.

이걸 Lazy하게 아래와 같이 코드 변경한다면 문제가 해결되겠죠?

 

 

이제 다시 한번 측정해보면 행도 정상적으로 400ms도 채 걸리지 않은걸 확인할 수 있습니다.

 

 

그러나, iPad에선 보다 많은 이미지 뷰가 나타날거니 이 350ms되는 행도 더 걸리게 될 수 있습니다.

즉, 마이크로 행이 항상 안전한것이 아니라는 증거죠.

 

지금은 메인 스레드에서 썸네일을 로드하고 있는데 이걸 백그라운드에서 로드해보면 어떨까요?

 

 

이렇게 task 모디파이어를 이용해 백그라운드에서 image 값을 작업하도록 해줍니다.

그럼 훨씬 행이 걸리지 않고 빨라집니다.

 

---

Async hang

행이 걸리는 케이스엔 동기 및 비동기 행이 원인인 경우도 있습니다.

 

 

동기적인 방식에선 작업이 오래 걸리면 순차적으로 행이지만,

비동기적인 방식에선 이벤트가 빨라도 나중에 메인 스레드에서 수행할 일부 작업을 지연했거나 다른 메인 스레드 작업이 발생한 후 이벤트가 발생할 수도 있습니다.

그런 다음 해당 이벤트를 처리하려면 이전 작업이 완료될때 까지 기다려야하죠.

각 개별 이벤트 처리에 대한 코드가 빠르게 완료되도 여전히 행이 발생합니다.

 

비동기 행은 기본 대기열의 dispatch_async 작업이나 Swift Concurrency 작업으로 인해 발생하는 경우가 많습니다.

 

한번 비동기 행을 수정해볼까요?

 

타임라인에 Swift Tasks를 추가하여 더 면밀히 볼 수 있습니다.

 

 

이렇게 스레드 트랙 헤더에 있는 작은 화살표를 클릭해 Task State를 선택하여 볼 수도 있습니다.

 

 

Swift Tasks 레인에 보면, 메인 스레드에서 여러 작업이 실행되고 있음이 명확히 표시됩니다.

메인스레드에서 Swift Tasks 부분에서 한 항목을 잡고 더 자세히 추적하여 보면 썸네일 계산 작업을 하고 있음을 확인할 수 있어요.

 

우리 위에서 task 뷰 모디파이어를 사용한것 기억하시죠?

task 동작을 보면 이렇습니다.

 

 

우선, View는 메인 액터에서 처리됩니다.

그에 따라 body도 당연히 메인액터로 처리되죠.

task 모디파이어의 클로저엔 주변 컨텍스트로부터 액터 격리를 상속하도록 주석이 추가됩니다.

 

사실 백그라운드 스레드에서 task 내부 로직이 처리될 수도 있지만, 현재 보면 image라는 UI 작업에 두고 있어요.

그리고 background.thumbnail하는것도 await과 같은 비동기를 사용하고 있지도 않죠.

 

그렇기에 이 코드는 메인 액터를 벗어나길 꿈꾸지만 실제론 메인 스레드에서 동기적으로 실행되는것입니다.

 

이제 메인액터에서 벗어나는 방법이 있어요.

 

await나 Task.detached를 이용하는것입니다.

 

await를 활용한 예시를 보면 이렇습니다.

우선, thumbnail getter의 정의를 비동기적으로 만듭니다.

 

 

async를 붙여주면 되죠.

 

 

그리고 사용부에서 await을 붙여주는것이죠.

 

그럼 이제 메인 액터에서 격리된 작업을 하게 됨으로 비동기 행 문제가 발생하지 않습니다!

 

여기까지 다양하게 메인 스레드가 사용중이라 응답하지 않는 메인 스레드를 탐색하고 그에 맞게 수정해봤습니다 😃

 

마지막으로 살펴볼 케이스는 메인 스레드가 차단된 경우입니다.

 

---

Blocked main thread hang

해당 경우에는 메인 스레드의 CPU를 거의 사용하지 않죠.

 

 

초기에는 CPU 사용이 있지만, 그 후에 걸린 행 지속시간엔 CPU 사용량이 아예 일절 없죠.

명확하게 메인 스레드가 차단된 상황입니다.

 

해당 타임라인을 더 확대하면 CPU 사용량 그래프에 개별 샘플도 표시됩니다.

 

 

여기서 각 마커는 Time Profiler가 가져온 샘플이에요.

샘플이 없는 시간 범위를 선택해도 Time Profiler는 이 시간동안에 데이터를 기록하지 않았기에 어떤 일이 일어났는지 모릅니다.

 

 

그래서 우리는 추가로 Thread State Trace라는 툴이 필요합니다.

 

 

추가가 되었으면, 이제 메인 스레드가 차단된 시점을 클릭하여 봅니다.

 

 

 

하단 Narrative 영역을 보면, 스레드가 왜 어디서 어떻게 차단되었는지 등 정보가 자세히 나와요.

여기선, 6.64초 동안 메인 스레드가 차단되었고 syscall인 mach_msg2_trap을 호출했기에 차단되었음을 나타냅니다.

우측 영역엔 다시 역추적 뷰가 있죠.

 

 

여기선 어떤것이 무겁고 그런것을 보는게 아니라 스레드를 차단한 mach_msg2_trap 시스템 호출의 정확한 역추적입니다.

호출 스택은 위에 표시되죠.

여기선 MLModel을 할당해서 syscall이 발생했고 이는 ColorizingService 타입의 객체 할당으로 인해 발생했음을 나타냅니다.

차례로 올라가면 body getter 클로저에 의해 호출되었네요!

 

여기서 코드로 보고싶은 부분을 더블 클릭하여 해당 코드를 볼 수 있습니다.

 

 

해당 코드에선 싱글턴을 사용하고 있습니다.

여기서 colorize 메서드는 비동기 함수입니다.

그러나 shared된 프로퍼티는 그렇지 않죠.

정적 속성이기에 처음 액세스할 때 느리게 초기화되고 동기적으로 발생합니다.

결국 여전히 기본 스레드에서 동기 호출이 발생하죠.

이는 공유 프로퍼티를 비동기로 설정하고 메인액터에서 벗어나게하여 해결해볼 수 있습니다.

 

또한 하나 짚고 넘어가야할건 타임라인에서 메인 스레드 CPU 사용량이 적다고 다 차단된것이 아닙니다.

단순 입력이 없어 효율적으로 쉬고 있을 수 있는것이죠.

그렇기에, 꼭 스레드 상태 툴이 아닌 행 툴로 살펴보는것이 좋습니다.

 

 

정리하면, 차단된 메인 스레드는 응답하지 않는 메인 스레드를 의미하는것은 아닙니다.

높은 CPU 사용량도 메인 스레드가 응답하지 않는다는 의미도 아니구요.

그러나, 메인 스레드가 응답하지 않으면 메인 스레드가 차단되었거나 사용중임을 의미하는것입니다.

메인 스레드가 실제로 응답하지 않는 간격에만 레이블을 지정하고 이를 잠재적인 행으로 표시합니다.

즉 모다 더 세부적인 사항을 고려해 행을 표시하게 되는것이죠.

 

결국 우리는 항상 100ms 이하로 행을 다루도록 신경써야하고, 다양한 행 발생 케이스를 알고 메인 스레드에서 적은 일을 처리하도록 백그라운드로 비동기적인 방법을 사용하는것을 권장합니다 🙏🏻

 

---

마무리

다양한 행 발생과 해결 케이스를 살펴보면서 확실히 많이 깨우친것 같습니다 😃

이제 일부로 행 발생시켜보고 해결해볼까요?ㅋㅋ

 

---

레퍼런스

Analyze hangs with Instruments - WWDC23 - Videos - Apple Developer