WWDC23 - Analyze hangs with Instruments

백상휘·2023년 6월 9일

언제나 내게는 숙제와도 같은 주제다.

이 발표에서는 hang 의 정의, hang 이 발생하는 원인, 이를 잡아내는 Instruments 에 대해 다룬다.

Instruments 에 대해 익숙하지 않다면 WWDC19 의 'Getting Started with Instruments' 를 보고 오라고 한다. 필자는 Instruments 를 써보긴 해서 사용방법은 알지만 활용방법에 대해서는 잘 모르고 있다고 판단하고 있다.

이 발표를 쭉 보고 위의 발표까지 볼 필요가 있는지 판단해보려 한다.

주의

해당 발표에서는 hang 을 찾는 것에 대해서는 다루지 않는다 WWDC22 의 'Track down hangs with Xcode and on-device detection' 에서 다루었다고 한다.

선행조건이 많은 발표라 느낌이 좋지 않다...

What is a hang?

hang 을 설명하기 위해 한 가지 예시를 든다.

전구가 있다. 전구에는 케이블을 꽂으면 불이 들어오고, 케이블을 빼면 불이 꺼진다. 이 과정은 바로바로 일어났으면 좋겠다.

근데 케이블을 꽂고 약 500ms 이후에 불이 켜진다고 해보자. 케이블을 뺐을 때도 500ms 이후에 불이 꺼진다고 해보자.

다른 예시도 들어보자. 대화를 하는 두 주체가 있다. 한 주체가 대화를 시도하고 한 주체가 대답을 한다. 이 사이에는 1초 간의 간격이 있다.

무엇이 hang 인가? 시간으로 이를 구별할 수 있을까? 전구의 예시는 hang 인가? 대화의 예시는 hang 인가?

발표에서 제시하는 기준은 모두에게 다를 수 있다. 하지만 내가 보기에도(애플에 설득당함) 아래와 같은 기준을 통해 hang 을 구별할 수 있을 것 같다.

0~100ms : Instant. hang 으로 볼 수 없음.
100~200ms : Circumstantial. 상황에 따라 hang 으로 판단될 수 있음. 대부분 Instant 로 판단
250~500ms : Micro Hang. hang report 에 포함됨. Instant 가 아닌 상황.
500ms~ : Hang.

여기서 또 다른 한가지를 더 구별해야 하는데 우리가 하는 상호작용은 2 가지로 구별할 수 있다.

Instant : 실제 결과를 도출해내기 위한 상호작용. (플러그를 꽂아 전구에 불이 들어옴)
Request-Response : 어떤 행동에 의해 물체끼리 상호작용 함. (서로 대화를 주고받음, 버튼을 클릭한 뒤 화면이 바뀜)

당연히 Request-Response 가 Instant 보다 느릴 수 밖에 없다. 그러므로 Instant 즉, '바로 실행되었다' 의 기준은 다음과 같다.

Event handling and redering loop

위에서 말한 내용을 종합해보면 상호작용할 때 가장 좋은 것은 UI 가 'Instant' 하게 작동해야 한다는 것이다.

이를 위해서는? non-UI 작업을 Main thread 로부터 완전 분리해야 한다.

작업을 분리하는 것은 컴파일러에서 미리 걸러주거나, 앱을 테스트하는 도중 발견되므로 상관이 없다. 충분히 예상 가능한 범위에서 일어나는 일이라는 것이다.

하지만 여기서는 2 개의 예상치 못한 경우가 발생할 수 있다.

Main Thread 의 작업 자체가 길어져서 Hang 이 발생한다.
Main Thread 의 작업이 실행되기 전 선행되어야 하는 작업을 실행해야 하는데, 다른 작업을 실행해야 해서 Hang 이 발생한다.

그러므로 우리가 목표로 해야 하는 것은 유저 상호작용이 발생한 이후(시작) 100ms 가 지난 시점에 Main Thread 의 작업이 시작되는 것을 목표로 해야 하는 것이다.

Busy main thread hang

이제부터 Xcode 에서 Profile 을 실행한다. Xcode 의 Product 메뉴에서 Profile 을 실행하면 앱이 빌드되고 설치된다. 실행은 되지 않는다.

그리고 Instruments 창이 열린다. 설정은 Xcode 의 배포 타겟과 기기 설정을 그대로 가져오게 된다.

발표에서 좋은 시작점이면서 뭐부터 시작해야할지 잘 모르겠을 때는 Time Profiler template 를 이용해보라고 한다.

Time Profile template 를 통한 Instruments 창을 확인해보면 Time Profiler instrument 와 Hangs instruments 가 존재한다. 아주 유용한 것들이다.

여기서 빨간 동그라미가 겹쳐있는 Record 버튼을 누르면 앱이 실행된다.

이 발표에서 보여준 Hang 은 'Choose Background' 버튼을 탭 하고나서 sheet 를 보여주는 화면의 Hang 을 보여주고 있다. 약 4초 정도 걸린 것 같다. 발표자의 말을 빌리자면 Severe Hang 이다.

그리고 Instruments 에도 이와 같은 사항이 기록 되었다.

위의 Hang 은 Main Thread 작업 자체가 오래걸려서 발생하였다. 다른 하나인 Main Thread 에 선행되어야 할 작업이 실행되지 않는 Hang 이 걸렸을 경우를 Instruments 에서는 아래와 같이 표현한다.

Main Thread 에서 어떤 작업이 이루어지고 있을까? 다시 Instruments 로 돌아가보자.

각 Instruments 에는 여러 스레드의 작업을 기록해 놓은 Call Stack 을 확인할 수 있다. 지금은 Main Thread 의 어떤 작업이 문제인지 알아보기 위해 Track 에서 Main Thread 를 선택하여 Call Stack 을 확인한다. 시간이 얼마나 걸렸는지 알 수 있기 때문에 어떤 함수가 문제인지 찾기 편리하다.

Severe Hang(빨간 부분) 에서 우클릭 한 뒤 option 키를 누른 상태에서 'Set Inspection Range' 를 클릭하면 자동으로 줌이 되어 Hang 부분만 화면에 들어오도록 한다.

Main Thread 의 CPU Usage 를 그래프로 표현하고 있는데, 60~90% 정도라면 상당히 높은 Usage 로 판단한다고 한다.

이는 빼도박도 못하는 Busy Main Thread, 즉 Main Thread 작업 자체 시간이 길었던 것으로 판단할 수 있는 것이다.

그럼 도대체 어떤 메소드가 문제란 말인가? 로그 한줄한줄 다 찾아봐야 하나? 오른쪽 하단에 'Heaviest Stack Trace' 가 도움이 될 것이다. 여기서 우리가 작성한 코드를 가리키고 있는 항목을 클릭해 본다. 'BackgroundThumbnailView.body.getter' 는 SwiftUI 의 뷰 내 body 프로퍼티를 가리키는 것으로 판단된다.

여기에 맨 아래 'Call Tree' 버튼을 클릭하면 Call Tree 에 나오는 항목들에 필터를 걸 수 있는데, 'system libraries' 항목을 클릭하여 작업자가 작성한 부분만을 볼 수 있도록 도움을 줄 수 있다.

마지막 스크린 샷의 선택된 항목을 오른쪽 클릭한 뒤 'Reveal In Xcode' 를 선택하면 실제 프로젝트의 소스코드를 바로 보여준다.

이제 우측 상단의 라이브러리를 추가해서 원인을 개선하는 것을 시연하는 영상을 보여주었다. 그것까지 포스팅에 넣으면 너무 길어지니 방법을 간단히 소개하는 것으로 마치겠다.

우측 상단의 라이브러리 추가 Context 화면에서 SwiftUI View Body 라이브러리를 추가한다.
View 코드에 For 루프를 2중으로 돌리는 부분이 있었다. 컨텐츠를 표시하는 양을 줄이는 것은 안된다. Grid 를 통해 모든 컨텐츠를 다 보여주는 것에서 LazyVStack 을 이용해 필요한 부분만 보여주도록 고친다.
아이패드에서 기능을 테스트하니 LazyVStack 에도 불구하고 스크린 크기에 의해 너무 많은 컨텐츠를 보여주기 때문에 Micro Hang(250~500ms 멈춤) 이 걸린다. 이는 Image 데이터를 받아서 렌더링 하는 작업 때문이었으므로, ProgressView 와 task 뷰 수정자를 이용해서 데이터를 불러오는 경우만 이미지를 렌더링 할 수 있게 처리하였다.

Async hang

위의 노력으로 화면 자체의 hang 은 없는데 Instruments 는 여전히 Hang 을 감지한다. 이는 sheet 화면이 표시되기 이전에 발생하는 Hang 이었다.

그래서 창을 바로 닫고 싶어도 닫을 수 없었다. Hang 때문에 상호작용이 먹히지 않는 것이다.

Hang 에 의해 상호작용이 불가해지는 현상은 2 개의 원인이 있다.

여기서 말하는 Synchronous/Direct Hang 은 User Input 에 대한 반응이 오래 걸리는 것을 말한다. Asynchronous/Delayed Hang 은 User input 에 반응은 하였으나 이를 처리하는 과정이 오래걸리는 것을 말한다.

참고로 Hang detection 은 위의 작업 시간을 계산하는 것으로 시작된다. 각 작업이 100ms 가 넘어가는지 조사하는 것이다. 100ms 가 넘어가면 Circumstantial, Micro Hang, Hang 등으로 구분 되는 것이다.

여기서도 문제를 해결해 나가는 과정을 글로 적어나가도록 하겠다. 사용한 도구들은 이미 위에 다 소개되었으니 이로 대체하도록 하겠다.

Heaviest Stack Trace 를 통해 가장 오래 걸린 코드를 살펴보니 .task 뷰 수정자였다. task 는 Swift Concurrency 를 이용한 Async 작업을 수행한다.
Swift Tasks 라이브러리를 추가한 후 다시 Instruments 로 자료를 수집한다.
여기서 일어난 일은 아래 이미지와 같이, @MainActor 에서 작동하는 View 프로토콜의 body 프로퍼티의 @MainActor context 와 task 뷰 수정자의 @MainActor context 가 다르다.
image 관련 작업은 synchronous 하였다. 그러므로 image 작업이 Main Thread 작업 중간에 끼어들어 작업을 지연시키는 원인이 되었다.
이를 해결하기 위해 2 가지를 고려하며, 첫 번째 고려사항이 채택된다.
- await 를 사용한다. (채택. 만약 뷰가 사라지더라도 자동으로 작업이 cancel 될 것임.)
- Task.detached() 를 사용한다. (기각. detached 자체가 무거운 작업임)
await 를 통해 작업의 일부를 멀티 스레딩 할 수 있게 되어 성능이 향상된다.

Blocked main thread hang

보이는 것처럼 Main Thread 에서 처음에는 CPU Usage 가 보이지만 한동안 CPU 를 사용하지 않고 있다.

Main Thread 자체가 작동하지 않아 생기는 Hang 을 체크하는 방법은 무엇일까? 우측 상단의 라이브러리 추가 버튼을 통해 'Thread State Trace' 를 추가해보도록 하자.

이를 통해 수집한 정보를 보자. 5초 이후 조금 있다가 CPU Usage 가 반응이 없다. 그리고 Thread State Trace 덕분에 여러가지 지표를 확인할 수 있다.

파란 선 이후의 타임라인을 선택하고 아래를 보자. 아래 목록의 특정 항목이 선택된다.

아까와는 다른 화면이다. Heaviest Stack Trace 등이 존재하지 않는다. Narrative view 는 스레드의 작업을 언제 그리고 왜 수행했는지 알려준다.

Blocked for 6.64 s (100.0% of mach_msg2_trap's duration) starting at priority 47.

잘 보이지 않을 수 있어 직접 적었다. 내용은 6.64s 동안 정지되었고, mach_msg2_trap 때문이라고 한다.

오른쪽의 backtrace 화면만 가져와 봤다. mach_msg2_trap 은 MLModel 에 존재하는 시스템에서 실행하는 함수인 것으로 추측된다.

MLModel 의 실행은 ColorizingService 라는 객체에 의해 실행된 것으로 보이며, 위에 shared 를 보아 싱글턴 객체로서 호출되었다. 이를 통해 하나의 스레드를 많은 작업이 공유할 수 있겠다는 생각이 든다.

그리고 바로 위, BackgroundThumbnailView.body.getter 의 첫번째 클로저에서부터 이 모든 작업이 시작됨을 알 수 있다.

'closure #1 in backgroundThumbnailView.body.getter' 항목을 더블 클릭하면 소스 뷰가 표시된다. 실제 코드는 아래와 같다.

struct ImageTile: View {
    // [...]
    
    // implicit @MainActor
    var body: some View {
        mainContent
            .task() { // inherits @MainActor isolation
                // [...]
                let colorizer = ColorizingService.shared // 싱글턴 객체를 task 안에서 참조하고 있음.
                result = try await colorizer.colorize(image)
            }
    }
}