エンジニア

Xcodeでパフォーマンス改善のために処理時間を計測する

投稿日：

こんにちは、名古屋スタジオでクライアントエンジニアをしている山本と申します。
本記事ではXcodeでiOSアプリを開発する際、パフォーマンス改善のために関数の処理速度を計測する方法について説明します。
（iOS 12以降が対象です）

処理速度の遅い関数を把握する

パフォーマンス改善においては、まずは遅い処理を把握することから始めます。
以下の様にTime Profilerを使用して、処理時間が多く掛かっている箇所を見つけます。

Xcodeの左上のRunアイコンを長押して、Build for Profilingに変更します。

Build for Profilingに変更

その後、左上にあるアプリアイコンを長押しで表示されるEdit Schemeを開きます。

Edit Scheme　を開く

Build ConfigurationをDebugに変更し、Executableに対象のアプリを設定します。

Build Configuration と Executable の設定

xcodeprojファイルのBuild SettingsのBuild Options内にあるDebugの項目をDWARF with dSYM Fileに変更します。

DWARF with dSYM Fileに変更

スマートフォンが接続されていることを確認し、Profileを実行するとアプリがビルド、インストールされ、Instrumentsアプリが立ち上がります。

Profile開始

Time Profilerを選択し、左上の赤いボタンをクリックするとアプリが起動します。

Time Profilerを選択

赤いボタンで起動

重い処理を通過した場合、グラフに変化が生じるため、調べたいタイミングで一時停止ボタンを押し、マウスドラッグで範囲を選択します。
すると、関数ごとの処理時間が一覧で表示され、Heaviest Stack Traceに処理時間のかかる順に関数が表示されます。

一時停止とマウスドラッグで範囲指定

処理時間の確認

詳細な処理時間を出力する

さて、ここまでで処理速度が遅い処理を大まかに把握することができたため、それらを細かく計測する方法を説明します。
InstrumentsのSignpostsを使用することでμsまで処理時間の計測が可能です。

Signpostsを使用する

初めにSignpostsを簡単に使用するためのクラスを示してから、使用方法について解説します。

Signpostsをマクロで使用するためのクラスを作成する

SignpostHelper.hppとSignpostHelper.cppファイルを作成します。

/**
 * @file SignpostHelper.hpp
 * @brief パフォーマンス改善デバッグ用のSignpostシングルトンクラス
 */

#ifndef SignpostHelper_hpp
#define SignpostHelper_hpp

#include <string>
#include <map>
#include <os/signpost.h>

#define SIGNPOST_START(tag, name, ...)\
{\
    SignpostHelper::getInstance()->init(tag);\
    auto itr = SignpostHelper::getInstance()->getIdMap().find(tag);\
    if(itr != SignpostHelper::getInstance()->getIdMap().end())\
    {\
        os_signpost_interval_begin(itr->second.first, itr->second.second, name, ##__VA_ARGS__);\
    }\
}\

#define SIGNPOST_END(tag, name, ...)\
{\
    SignpostHelper::getInstance()->init(tag);\
    auto itr = SignpostHelper::getInstance()->getIdMap().find(tag);\
    if(itr != SignpostHelper::getInstance()->getIdMap().end())\
    {\
        os_signpost_interval_end(itr->second.first, itr->second.second, name, ##__VA_ARGS__);\
        SignpostHelper::getInstance()->getIdMap().erase(itr);\
    }\
}\

class SignpostHelper{
public:

    /**
     * @brief インスタンス取得
     * @return SignpostHelperのインスタンス
     */
    static SignpostHelper* getInstance();

    /**
     * @brief カテゴリーを登録
     * @param category カテゴリー
     */
    void init(const std::string& category);

private:

    std::unordered_map<std::string, std::pair<os_log_t, os_signpost_id_t>> _idMap;

public:

    /**
     * @brief LogとIDのMapを取得
     * @return idMap
     */
    inline std::unordered_map<std::string, std::pair<os_log_t, os_signpost_id_t>>& getIdMap(){ return _idMap; };

};

#endif /* SignpostHelper_hpp */

/**
 * @file SignpostHelper.cpp
 * @brief パフォーマンス改善デバッグ用のSignpostシングルトンクラス
 */

#include "SignpostHelper.hpp"

#define SUBSYSTEM "subsystem"

SignpostHelper* SignpostHelper::getInstance()
{
    static SignpostHelper instance;
    return &instance;
}

void SignpostHelper::init(const std::string& category)
{
    if(_idMap.find(category) == _idMap.end())
    {
        auto log = os_log_create(SUBSYSTEM, category.c_str());
        _idMap.emplace(std::make_pair(category,　std::make_pair(log,　os_signpost_id_generate(log))));
    }
}

作成したクラスを使用してos_signpostに出力する

上記クラスを作成後、調査したい関数が含まれる箇所へインクルードし、計測したい関数のあるフォルダでインクルードし、SIGNPOST_START()とSIGNPOST_END()で囲みます。

SIGNPOST_START("Category","Name","StartMessage");
//計測したい処理
func();
SIGNPOST_END("Category","Name","EndMessage");

※引数は好きな文字列に置き換えても大丈夫ですが、第一引数と第二引数はStartとEndで一致させる必要があります。

最初の手順と同じようにビルドして、Time Profilerを起動します。
右上の+からos_signpostを追加します。

os_signpostの追加

記述した箇所が実行されると、os_signpost内にSignpostHelper.cppで指定したsubsystemの欄が表示されます。
実行回数、最小処理時間、最大処理時間、平均処理時間が表示され、StartMessageとEndMessageが出力されていることが確認できます。

StartMessageとEndMessageの出力確認

これで詳細な処理時間とログが出力できるようになりました。
また、Instrumentsの計測データはファイルとして保存できるので、保存しておくことで前のバージョンとの処理速度の比較などが容易になります。

さて、ここまでで大まかに遅い処理が把握できたので、ループ処理内の関数で引数が違う場合などに動作が重くなっている箇所を特定する方法を説明します。

ループ処理の計測方法

Messageの引数にフォーマット指定子を使用できるため、ループ処理のどのタイミングで遅くなっているのか把握できます。
例としてiが50の時に1秒止まる処理をmainループが通る箇所のどこかに記述してみます。

    for(int i = 0; i<100; i++)
    {
        SIGNPOST_START("Category","LoopCheck","LoopStart:%d",i);
        // 50の時だけ1秒止めてみる
        if(i==50)
        {
            sleep(1);
        }
        SIGNPOST_END("Category","LoopCheck","LoopEnd:%d",i);
    }

os_signpostを確認すると、50の時だけ処理に1秒かかっていることが確認できます。

ループの確認結果

まとめ

以上、パフォーマンス改善のために処理時間を計測する方法の説明でした。
os_signpostを使用するとμsという細かい単位で処理速度の計測ができるため便利です。
CCLOGなどのログ出力を使用する場合は、目的のログを探すことや保存をすることが大変になってしまうので、XcodeでiOSアプリのパフォーマンスチューニングをされている方は是非試してみてください。

採用情報

ワンダープラネットでは、一緒に働く仲間を幅広い職種で募集しております。

-エンジニア
-, ,

© WonderPlanet Inc.