RunWay 1.4 (10) 보내지 않은 종료 신호
워치에서 러닝을 끝냈는데 아이폰이 계속 도는 문제를 반년 가까이 못 잡고 있었다. 간헐적이라 조건을 모르고, 다시 해보면 멀쩡했다.
시뮬레이터에서 20km를 돌리다가 그대로 재현됐다. 아이폰이 아직 돌고 있는 상태에서 로그를 열었다.
왼쪽 워치는 끝나서 요약 버튼이 떠 있는데, 오른쪽 아이폰은 REC 가 켜진 채로 20.09km, 1시간 29분을 계속 세고 있다.
아이폰이 받은 1609개
종료 신호가 도착한 흔적이 없었다. receive 가 한 줄도 안 찍혔다.
그래서 아이폰이 받은 것을 전부 셌다. 프레임워크 로그에는 앱이 뭘 했든 다 남는다.
1
2
1609개
전부 45~46바이트
워치가 5초마다 보내는 심박·케이던스다. 종료 시각 직전 것까지 정확히 그 크기였다.
1
2
3
12:27:30.514 45
12:27:36.475 45
12:27:41.516 45 <- 마지막
마지막 줄을 종료 신호로 착각할 뻔했는데 크기가 같았다. 그냥 5초마다 오던 건강 데이터였고, 워치가 끝나면서 그게 멈춘 것이다.
보낸 적이 없는 신호
받는 쪽을 봤으니 보내는 쪽을 봤다. 워치의 wcd 는 앱과 별개 데몬이라 로그가 제대로 남는다.
1
2
종료 이후 722줄
그중 아웃바운드 0개
sendMessage 도 transferUserInfo 도 안 불렸다. 둘 중 하나라도 불렸으면 반드시 남는다.
신호가 가다가 사라진 게 아니라 애초에 안 나갔다.
반년 동안 “배달이 유실된다”로 보고 있었다. 고칠 자리가 완전히 다른 곳이었다.
조용히 빠져나가는 자리 세 곳
워치는 자기 일을 다 했다. 기록을 저장하고 요약을 보여주고 홈까지 돌아갔다. 그런데 신호만 안 갔다.
보내기까지 가는 길에 막힐 수 있는 자리가 셋인데, 셋 다 아무 말 없이 돌아선다.
1
2
3
4
5
// 1. 세션이 없으면 아무 일도 안 일어난다
func stopWorkout() {
stopOrigin = .local
session?.stopActivity(with: Date())
}
옵셔널 체이닝이라 세션이 nil 이면 그냥 지나간다. 상태 변화 콜백이 없으니 그걸 받아 신호를 보내는 자리도 안 돈다.
1
2
3
4
// 2. 워치가 시작한 러닝이면 안 보낸다
if HealthKitService.shared.startOrigin != .local {
watchConnectivityService.sendStopSignal()
}
1
2
// 3. 여기서 돌아서면 로그도 없다
guard WCSession.default.activationState == .activated else { return }
셋 중 어디서 멈췄는지 알 방법이 없었다. 그래서 각 자리에 한 줄씩 남기게 했다.
워치 로그를 못 읽는 문제
원래는 워치 쪽 로그를 읽어서 바로 가리려고 했다. 그런데 워치 시뮬레이터가 앱 안에서 찍는 로그를 아예 저장소에 안 남긴다.
1
2
wcd, healthd 같은 별도 데몬 정상
앱 프로세스 안에서 찍은 것 0줄
직접 넣은 로거도, HealthKit 프레임워크도, WatchConnectivity 도 전부 0줄이다. 그래서 세 자리 중 어디인지는 아직 못 가렸다.
다만 1번 자리의 로그는 아이폰에서도 찍힌다. 같은 공유 코드라서, 워치 로그를 못 받아도 절반은 보인다.
심박이 끊긴 자리
같은 러닝의 FLIGHT DATA RECORDER 를 열어보니 답이 그림으로 있었다.
PACE 는 끝까지 출렁이는데 BPM 만 오른쪽 끝에서 평평하다. 그 자리가 워치에서 종료를 누른 순간이다. 아이폰은 자기 GPS 로 계속 달렸고 심박만 더 안 들어왔다.
아이폰은 워치가 끝난 걸 이미 알고 있었다. 알아차리지 못했을 뿐이다.
1
2
3
4
5
6
7
} else {
guard let heartRate = message["heartRate"] as? Double, ... else { return }
Task { @MainActor in
vm?.healthData.heartRate = heartRate
// 생략
}
}
받아서 쓰기만 하고 언제 마지막으로 왔는지는 안 들고 있었다.
간격을 재보니 아주 규칙적이었다.
1
5.0s 5.0s 6.0s 5.0s 5.0s 6.0s 5.0s 5.0s
1609개 중 흔들림이 1초 안쪽이다. 끊기면 아주 뚜렷하게 끊긴다. 종료 신호가 왜 안 왔는지와 무관하게 이것만으로 알아챌 수 있다.
묻기만 하는 이유
처음에는 자동으로 끝내려고 했다. 그런데 끝난 것과 잠깐 안 닿는 것을 구분할 방법이 없다.
주머니에 폰을 넣고 뛰다가 잠깐 끊겼다고 러닝을 멋대로 끝내버리면 기록이 날아간다. 그건 지금 버그보다 나쁘다.
그래서 묻기만 한다.
1
2
3
4
5
LOST CONTACT
워치에서 데이터가 1분 넘게 오지 않았어요.
워치에서 러닝을 끝냈다면 여기서도 끝낼 수 있어요.
[러닝 종료] [계속 뛰기]
조건은 셋을 다 걸었다.
1
2
guard isRunning, !hasAskedWatchEnded, let last = lastWatchHealthAt else { return }
guard Date().timeIntervalSince(last) >= watchSilenceThreshold else { return }
두 번째 줄의 lastWatchHealthAt 이 제일 중요하다. 한 번도 안 왔으면 nil 로 남는다. 워치 없이 뛰는 사람에게는 존재하지 않는 기능이 된다. 이게 없으면 워치를 안 찬 러닝이 시작하자마자 끝나버린다.
hasAskedWatchEnded 는 한 번 끊김에 한 번만 묻는다. 데이터가 다시 오면 풀려서, 끊겼다 붙었다 하면 그때마다 새로 묻는다.
기준은 60초로 잡았다. 보내는 간격의 12배다. 묻기만 하는 거라 늦게 떠도 손해가 없고, 자주 뜨는 쪽이 더 성가시다.
20km가 넘어가니 끌리기 시작한 화면
21.7km 기록을 열어보니 두 자리에서 끊겼다.
1
2
요약 화면에서 스플릿을 스크롤할 때
FLIGHT DATA RECORDER 로 넘어갈 때
증상이 다르니 원인도 다를 거라고 보고 따로 봤다. 결과적으로 원인이 셋이었다.
줄마다 전체를 다시 정렬하던 스플릿
1
2
3
private func isFastest(_ pace: Double) -> Bool {
sortedSplits.count >= 2 && pace > 0 && pace == minPace
}
스플릿 한 줄은 자기가 이 러닝에서 제일 빠른지, 느린지, 심박이 제일 높은지, 낮은지, 케이던스는 어떤지를 여섯 번 묻는다. 그래야 값 옆에 화살표를 붙일지 정할 수 있다.
그런데 minPace 가 계산 프로퍼티였다.
1
2
3
private var sortedSplits: [SwiftDataSplit] { splits.sorted { $0.order < $1.order } }
private var validPaces: [Double] { sortedSplits.map { $0.pace }.filter { $0 > 0 } }
private var minPace: Double { validPaces.min() ?? 0 }
물을 때마다 정렬부터 다시 한다. 20km 러닝이면 스플릿이 22개다.
1
22줄 × 6번 = 한 번 그릴 때 정렬 132번
스크롤하면 그게 또 돈다. splits 가 SwiftData 객체 배열이라 값 하나 읽는 비용도 평범한 배열과 다르다.
전부 init 에서 한 번만 구하게 했다. 132번이 1번이 됐다.
기준선을 매 프레임 평균 내던 자리
1
2
3
4
5
private var paceTarget: (center: Double, tolerance: Double)? {
// 생략
let moving = samples.map(\.pace).filter { $0.isFinite && $0 > 0 }
return (center: moving.reduce(0, +) / Double(moving.count), tolerance: 0)
}
Free Flight 의 평균선을 구하는 자리다. 이것도 계산 프로퍼티인데 그래프에 넘기는 값이라, body 가 돌 때마다 표본 1158개의 페이스를 전부 꺼내서 평균을 다시 냈다.
여기가 제일 비쌌다. samples 가 SwiftData 객체라 .pace 하나 읽는 것도 저장소를 거친다.
매 프레임 새로 만들던 배열
1
FDRLaneView(values: samples.map(lane.value), ...)
이것도 body 안이었다. 끌 때마다 1158개짜리 배열을 네 개 새로 만든다. 세로 범위를 구하는 자리도 마찬가지로 거르기 한 번에 정렬 두 번이 매 프레임 돌았다.
저장된 기록은 값이 안 바뀐다. 한 번만 구하면 된다.
| 프레임당 | 전 | 후 |
|---|---|---|
| 스플릿 정렬 | 132번 | 0 |
| 표본 페이스 읽기 | 1158번 | 0 |
| 배열 생성 | 1158 × 4 | 0 |
| 범위 정렬 | 8번 | 0 |
들어가는 길을 막고 있던 읽기
화면 전환이 끊기는 건 다른 문제였다.
1
.onAppear(perform: loadRecords) // 표본 1158개를 저장소에서 읽는다
onAppear 는 화면이 밀려 들어오는 중에 돈다. 그동안 메인 스레드가 묶여서 전환 자체가 끊긴다.
1
2
3
4
.task {
await Task.yield()
loadRecords()
}
첫 프레임이 그려진 뒤에 읽게 바꿨다. 전환은 매끄럽게 끝나고 내용이 조금 늦게 들어온다.
읽는 중인지 아닌지를 구분하는 상태도 같이 넣었다. 그게 없으면 “되감을 수 없어요”가 한 번 번쩍이고 사라진다. 표본이 비어 있는 상태와 아직 안 읽은 상태를 둘 다 samples.isEmpty 로 보고 있었기 때문이다.
남겨둔 것
읽는 일 자체는 그대로 메인 스레드에서 돈다. 전환이 끊기진 않지만 내용이 들어오는 데 0.2초쯤 걸린다.
없애려면 백그라운드에서 읽어야 하는데, SwiftData 객체는 다른 스레드로 못 넘긴다. 평범한 구조체로 바꿔야 하고 그러면 이 기록을 쓰는 화면 셋을 다 건드려야 한다. 20km 에서 0.2초면 아직 버틸 만해서 뒀다.
아직 둘 다 살아 있는 가설
재현된 20km 다음에 25km 를 한 번 더 돌렸다. 이번엔 정상이었다.
1
2
3
4
러닝 길이 114.3분
배달 0.90s
저장 182ms
화면 전환 584ms
지금까지 모은 걸 시간 순으로 늘어놓으면 이렇다.
| 시간 | 결과 |
|---|---|
| 2~3분 × 5 | 전부 성공 |
| 40분 | 실패 |
| 45분 | 성공 |
| 62분 | 성공 |
| 90분 | 실패 |
| 114분 | 성공 |
실패가 중간중간 박혀 있다. “N분을 넘기면 난다”는 선은 없다.
아직 지워지지 않은 길이
선이 없다고 길이가 무관한 건 아니다. 짧은 러닝은 다섯 번 다 성공했고, 긴 쪽은 다섯 번 중 두 번 실패했다.
임계값이 아니라 확률로 보면 그대로 들어맞는다. 길수록 뭔가 어긋날 기회가 많아지는 것이고, 한 번 성공했다고 지워지는 종류의 가설이 아니다.
세션이 아직 안 깨어 있던 자리
어제 “조용히 빠져나간다”고 지목해둔 세 자리 중 하나가 실제로 찍혔다.
1
2
3
13:31:48.892 [stopWorkout] 세션=있음 startOrigin=local
13:31:49.462 [pfd.gone]
13:31:51.048 [send.notActivated] 세션이 활성 상태가 아니라 못 보냄
1
2
3
4
guard WCSession.default.activationState == .activated else {
RemoteStopLogger.log("send.notActivated", "세션이 활성 상태가 아니라 못 보냄")
return
}
이 줄을 안 넣었으면 아무 일도 없었던 것처럼 보였을 자리다. 세션 활성화는 앱이 켜진 뒤 비동기로 끝나는데, 그 전에 종료를 누르면 신호가 조용히 버려진다.
20km 실패가 설명되지 않는 이유
솔깃했지만 맞춰보니 안 맞았다.
1
2
워치 앱 PID 43336 10:57 시작
20km 러닝 10:58 ~ 12:27
러닝 내내 같은 프로세스였다. 재시작이 없었으니 세션은 한참 전에 활성화됐을 것이다.
13:31 의 그 로그는 아이폰 앱이 막 켜진 직후의 다른 상황이었다. 같은 함수의 같은 가드이긴 해도, 20km 실패의 원인이라고 말할 근거가 없다.
실제로 겪었을 때 앱을 백그라운드로 내린 적도 없다고 한다. 다만 워치 앱은 사용자가 아무것도 안 해도 watchOS 가 내렸다 올릴 수 있어서, 그쪽까지 지워지는 건 아니다.
지금 말할 수 있는 것
1
2
3
4
그 가드가 실제로 걸리는 자리는 맞다 로그로 확인
20km 실패는 그걸로 설명되지 않는다 재시작이 없었다
길이는 임계값이 아니다 114분이 멀쩡했다
길이가 무관한 것도 아니다 짧은 건 다섯 번 다 성공
나머지는 전부 후보다. 다음 재현에서 세 줄 중 뭐가 찍히는지, 아니면 셋 다 안 찍히는지가 갈라줄 것이다. 셋 다 안 찍히는데 보낸 흔적도 없으면 아직 모르는 네 번째 자리가 있다는 뜻이다.
정리
화면이 안 빠지는 건 눈에 보이는 증상이고, 진짜 피해는 따로 있었다.
1
2
12:27:40 워치에서 종료 여기서 끝났어야 한다
12:35:12 아이폰에서 종료 실제로 저장된 시각
7분 30초, 1.7km 가 더 붙었다. 20km 를 뛰었는데 21.7km 로 남았다.
기록이 하나 더 생기거나 덮어써진 게 아니다. 저장된 건 하나뿐이고, 그 하나가 틀렸다.