STORES Product Blog

こだわりを持ったお商売を支える「STORES」のテクノロジー部門のメンバーによるブログです。

OSSignposterを活用したiOSアプリのパフォーマンス計測

STORES レジ iOS/Androidアプリ Swift

こんにちは、 STORES レジ を開発しているiOSエンジニアの @miichan_ocha です！

みなさん、iOSアプリのパフォーマンスを計測していますか？ iOSアプリは Xcode Instruments を使ってアプリのさまざまな状態を計測できます。その中でも、パフォーマンス計測のときによく使われるのは Time Profiler ではないでしょうか。Time Profiler は Instruments 上で選択した範囲において、どの関数がどれくらいの時間 CPU を使用していたかを計測してくれる便利なツールです。

Time Profiler

CPU使用率の高い関数を特定できても Time Profiler だけではその関数の

  • 個々の実行時間が長いのか
  • 個々の実行時間は短いが、大量に実行されているのか
  • 特定の条件でだけ実行時間が長いのか

のようなことまでは分かりません。しかし、アプリのパフォーマンス改善時にはどのケースなのかによって改善の方針（関数の呼び出し側を改善するべきなのか、関数の処理自体を改善すべきなのか）が異なるため、これらを把握することは非常に重要です。

そのような時に役立つのが OSSignposter です。OSSignposter を使うと特定の処理の個々の実行時間や実行回数を記録し、それを Instruments 上で可視化できます。これにより、CPU 使用率の高い関数が個々の処理にどれくらいの実行時間がかかったのか・どれくらいの頻度で呼ばれたのかを把握できます。

この記事では OSSignposter の基本的な使い方と Instruments での可視化方法、そして STORES レジ で実際に OSSignposter を使ってパフォーマンス計測を行なった事例をご紹介します。

※本記事内の説明は Xcode 16 の環境で書かれたものです。

OSSignposter の基本的な使い方

OSSignposter は os_signpost(_:dso:log:name:signpostID:) 関数が新しくなったもので、iOS 15.0+ で使用できます。

OSSignposter には様々なAPIがありますが、今回はその中から特定の処理の実行時間を測る beginInterval(_:id:) と endInterval(::) について取り上げます。

基本的な使い方は以下で、最初に OSSignposter のインスタンスを作成した後 signpost ID と呼ばれる同一設定・スコープの計測区間を識別するためのIDを生成し、計測したい処理を beginInterval と endInterval で囲います。beginInterval(:id::) と endInterval(::_:) を使って第三引数にメッセージを渡すこともできます。

import Foundation
import os

// OSSignposterインスタンスの作成。subsystemとcategoryを指定することも可能。
let signposter = OSSignposter()

func sampleFunction(_ signposter: OSSignposter) {
    // makeSignpostID() を使って signpost ID を生成する
    let signpostID = signposter.makeSignpostID()

    // beginInterval を呼んで開始
    // 第一引数の name は beginInterval/endInterval で同じ文字列を指定すること
    // 第二引数の id は生成した signpost ID を渡す
    // 戻り値の OSSignpostIntervalState 型のオブジェクトを保持する（endInterval の引数で渡すため）
    let state = signposter.beginInterval("sampleFunction", id: signpostID)

    // 計測対象
    let message = innerFunction()

    // endInterval を呼んで終了
    // 第二引数の state に beginInterval の戻り値の OSSignpostIntervalState 型オブジェクトを渡す
    // 第三引数にメッセージを付与することも可能。文字列補完で渡すことで SignpostMetadata に自動で変換してくれる
    signposter.endInterval("sampleFunction", state, "\(message)")
}

func innerFunction() -> String {
    // 1秒間スリープしてメッセージを返す
    Thread.sleep(forTimeInterval: 1.0)
    return "inner function return message"
}

...
// 適当な場所で関数を呼ぶ
sampleFunction(signposter)

この他にも、単発のイベントを記録する emitEvent(_:id:) や beginInterval/endInterval より柔軟性が低いもののより簡潔な記述が可能な withIntervalSignpost(_:id:around:) などのメソッドも OSSignposter は提供しているので、詳細な使い方に関しては公式のドキュメントをご参照ください。

Instruments での可視化方法

では、先程の例で OSSignposter を使って記録したものを Instruments 上で可視化してみましょう。

アプリの Profile を開始

まずは Xcode の Product > Profile を選択（または ⌘I）してアプリの Profile を開始します。

ビルド完了後、Instruments が起動するので適当なテンプレートを選択して「Choose」ボタンを選択します（例では「Time Profiler」テンプレートを選択しています）。

os_signpost を追加

選択後に表示されるファイル内で、必ず計測前に 「+ Instrument」を押して「os_signpost」Instrument をドラッグ&ドロップで追加します。

Instruments で計測

左上の計測開始ボタンを押して計測を開始し、計測が終わったら計測停止ボタンを押せば計測完了です。

計測後「os_signpost」Instrumentを展開すると、さきほどの計測区間のデータが可視化されています。 そして End Message には先程の例の endInterval(_:_:_:) の第三引数で指定したメッセージが表示されていることも分かります。また、同一設定の計測区間の実行回数や平均実行時間なども確認できます。

OSSignposter を使ったパフォーマンス計測事例

STORES レジ で実際に OSSignposter を使ってパフォーマンス計測を行なった事例をご紹介します。

※サンプルコード内に出てくるメソッド名などは実際のものとは異なります。

Busy Main Thread 起因の Hang が発生していた

STORES レジアプリ開発中に Hang1 の発生に気付きました。 WWDC 2023の「Analyze hangs with Instruments」では、メインスレッドが応答しない理由は2種類あると述べられています。ひとつはメインスレッドが他の作業で忙しい「Busy Main Thread」という状態、もうひとつはメインスレッドが他の場所で行われている作業を待っている「Blocked Main Thread」という状態です。

Instruments を使ってアプリのパフォーマンスを計測したところ Hang 発生箇所でメインスレッドの CPU 使用率が100%に張り付いていたため、Busy Main Thread 起因の Hang が発生していることが分かりました。

Hangが発生し、メインスレッドの CPU 使用率が100%になっている

CPU 使用率の高い関数を Time Profiler で特定

次に Time Profiler を使って Hang 発生時にメインスレッドの CPU 使用率が高かった関数を特定していきました。調査を進めると、makeLogMessage() というログを送る際のメッセージを生成するメソッドの CPU 使用率が高いことが分かりました。

makeLogMessage() のCPU使用率が高い

しかし、Time Profiler だけではこの makeLogMessage() メソッドの

  • 個々の実行時間が長いのか
  • 個々の実行時間は短いが、大量に実行されているのか
  • 特定の条件でだけ実行時間が長いのか

といったことまでは分かりません。そこで、OSSignposter を使ってこれらを把握できるようにします。

OSSignposter を使って CPU 使用率の高い関数を計測

STORES レジアプリでは Action と呼ばれる enum が定義されており、各アクションをアプリ内で送ることでそのアクションに対応した処理を行っています。そして、各アクションに対応するログメッセージを生成して返すメソッドが makeLogMessage() です。

enum Action: Equatable, Sendable {
    case item(ItemAction)
    case user(UserAction)
    ...

    func makeLogMessage() -> String {
        // "[user]: logout" のような各アクションに対応するログメッセージを生成して返す
        ....
        return message
    }

このメソッドを以下のように OSSignposter を使って計測しました。endInterval には生成したログメッセージを渡すことで、どのアクションのログメッセージを生成したのかを Instruments 上で識別できるようにしています。

import os

private let signposter = OSSignposter()
...
@MainActor
private func sendLog(for action: Action) {
    let signpostID = signposter.makeSignpostID()
    let state = signposter.beginInterval("makeLogMessage", id: signpostID)
    let message = action.makeLogMessage()
    signposter.endInterval("makeLogMessage", state, "\(message)")
    Logger.postLog(message)
}

再計測

再度アプリのパフォーマンス計測を行い計測結果を Instruments 上で確認したところ、いくつかのアクションのmakeLogMessage() メソッドの実行時間が非常に長く、それによりメインスレッドの CPU 使用率が高くなり Hang が発生していることが分かりました。つまり、この makeLogMessage() メソッドは「特定の条件でだけ実行時間が長くなる」ケースでした。

一部の makeLogMessage() メソッドの実行時間が非常に長い（赤線）

ここまでの調査でこの makeLogMessage() メソッドの処理自体に問題があることが分かったため、メソッドの処理を改善し、最終的にすべてのアクションのログメッセージの生成を短時間で行うことができるようになりました。その結果、メインスレッドの CPU 使用率が低くなり Hang も解消できました。

改善後

まとめ

OSSignposter を使うことで特定の処理の個々の実行時間や実行回数を記録し、それを Xcode Instruments 上で可視化できます。 Time Profiler で CPU 使用率の高い関数を特定するだけでなく、必要に応じて OSSignposter も活用することでより効果的なパフォーマンス計測と改善ができるでしょう。

WWDC 2025の「Embracing Swift concurrency」で紹介された「Approachable Concurrency」の流れもあり、iOS アプリ開発者がアプリのパフォーマンスを計測し改善していく重要性はさらに高まっていくのではないでしょうか。 この記事が、みなさまが開発されている iOS アプリのパフォーマンス改善に少しでも役立てば幸いです。最後まで読んでいただきありがとうございました！

  1. アプリがユーザーの操作に反応しなくなってしまう（メインスレッドが応答していない）状態のこと↩