hrfmmr's blog

Xcodeのビルド時間を監視する

Posted on | 842 words | ~4 mins

Context

  • とあるコードベースでXcodeのビルド時間がインクリメンタルビルドですら3分近くかかる問題がある
  • 「ビルド時間おそいですね」課題感は共通認識なものの、総量として定量的にみてどれくらいの問題の大きさなのかが把握できていない状況でもある
  • ビルド時間を開発速度のhealthcheck的な指標としてモニタリングしたい

どうやるか

  • XCMetricsというTHEソレのようなOSSをspotifyが公開していたりする
    • github repo: https://github.com/spotify/XCMetrics
    • (v0系ではあるものの)1st releaseが2021/01とわりと最近
    • vapor製
    • Swift大統一
    • dashboard UIがイケてる
      • image
      • サービス然りアプリ然りspotifyちょいちょいイケてる
        • 日本からリモートで働き口ないか探してみたが、BizDev/マーケ方面でしか募集してなさそう(Engineering職はもっぱら欧米リージョン。格差社会)
  • XCMetricsはつかえるか🤔
    • Backend Deploymentをみると、アプリケーション/DBサーバの運用が必要
      • localhostでつかう分にはDocker imageも提供されているしサクッと動かせる
      • 業務での運用を考えると、サーバをお守りするのはセキュリティ事がついてまわるので話が変わってくる
      • アプリケーションサーバについてはCloud Runにオフロードする構成もとれるっぽいが、別でCloud SQLもとなるとコストの割高感が否めない..
    • インフラ管理不要なマネージドに寄せつつ低コストでおなじようなことをやりたいというモチベーションがあったりする
  • XCMetricsはビルドログ収集どうやってるの
    • XCLogParserをつかっている
      • とは
        • Xcodeがビルドログとして~/Library/Developer/Xcode/DerivedData/に吐き出す.xcactivitylog(gzip圧縮されたSLF encodedなファイル(?))があって、
        • これをparseするとビルドの詳細情報(どのschemeで/どのtargetで/どのソースファイルで/どれだけビルド時間がかかったか情報etc)がとれる
        • このparse処理をラップしてビルドメトリクス情報をhtmlやjsonで出力できる、というツール
      • なにげにmain contributorがXCMetricsと同じspotifyの人
  • ビルドログ情報はXCLogParserから取得できるから、以下が揃えばXCMetricsでやってるようなビルド時間可視化はいける
    1. ログデータの加工(postBuildScript)
    2. ログデータの保存(DB)
    3. ログデータの可視化(のfrontend)
  • 「データがあってそれを可視化」といったらBigQuery+Data Portalの構成が降ってくる(というかWebアプリ以外だとそれしかおもいつかない..)

構成

Overview

  • a.) Xcodeでビルドが実行されたら、postBuildScriptによりxclogparserでビルドログ情報を抽出&可視化用に加工したデータ(json)をs3にupload
  • b.) BigQuery Data Transfer Serviceでs3にuploadされたデータをBigQueryにロード(定期or手動実行)
  • c.) Google Data Portalでビルドメトリクスを(dashboardとして)可視化
image

Post Build Scriptフェーズ

image

各フェーズ詳細

    1. ビルド開始
    1. ビルド完了後、Post Build Scriptとしてlauncherスクリプトを実行
    • launcherとは
      • 本体のスクリプトをbackground実行するためのスクリプト
      • なぜ
        • .xcactivitylogがXcodeからdumpされるのはPost Build Processの後になる為
        • Post Build Scriptでいくらsleepしたとしてもビルドログは一生dumpされない
        • すると「今ビルドしたもの」より1つ前のビルドログが参照されてしまう
          • eg. 「Cleanビルドしたが、ビルドの方ではなくCleanの方のログが参照されてしまう」
        • ので、background実行を挟むことでPost Build Processを踏ませ、ビルドログのdumpを待ち受けるといったworkaroundが必要というかんじ
        • cf. https://github.com/MobileNativeFoundation/XCLogParser#tips--tricks
    1. ビルド後、.xcactivitylogが/path/to/DerivedData/にdumpされる
    1. 本体のPost Build Scriptが実行される
    1. 内部処理でxclogparserによるビルドログのparse結果を取得
    1. これをBQテーブルスキーマに合わせて加工
    1. 加工したビルドログデータをs3にupload

やっていき

Post Build Scriptを仕込む

  • XcodeGen project.yml

    ...
targets:
  xxx:
    ...
    postBuildScripts:
      - name: Upload xclogparser result JSON to S3
        script: |
          cd "$PROJECT_DIR" && \
          S3_BUCKET=s3://xcbuildmetrics.example.com \
          scripts/post_build_script_launcher.sh \ # 先述のlauncherスクリプト
          python3 scripts/xcbuildmetrics_uploader.py # s3にビルドログをuploadする本体スクリプト

  • scripts/post_build_script_launcher.sh

    executable=$1
shift;
$executable "$@" <&- >&- 2>&- &

  • scripts/xcbuildmetrics_uploader.py

    from __future__ import annotations

import inspect
import json
import logging
import os
import pathlib
import subprocess
import tempfile
import time
import typing as t
from copy import deepcopy
from dataclasses import asdict, dataclass
from datetime import datetime
from enum import Enum

JSON = t.Dict[str, t.Any]

logging.basicConfig(
    handlers=[
        logging.FileHandler(".xcbuildmetrics_uploader.log"),
        logging.StreamHandler(),
    ],
    level=logging.DEBUG,
    format="[%(levelname)s](%(process)s-%(threadName)s) @%(asctime)s - %(name)s.%(filename)s#%(funcName)s():L%(lineno)s - %(message)s",
)

logger = logging.getLogger(__name__)


@dataclass
class BuildStep:
    startTimestamp: float
    compilationDuration: float
    schema: str
    fetchedFromCache: bool
    subSteps: list[BuildStep]
    machineName: str
    type: str
    schema: str

    def __post_init__(self):
        self.subSteps = [BuildStep.from_dict(x) for x in self.subSteps]

    @classmethod
    def from_dict(cls, data: JSON) -> BuildStep:
        attrs = inspect.signature(cls).parameters
        return cls(**{k: v for k, v in data.items() if k in attrs})

    def flatten(self) -> list[BuildStep]:
        steps: list[BuildStep] = []
        no_sub_steps = deepcopy(self)
        no_sub_steps.subSteps = []
        steps.append(no_sub_steps)
        for subStep in self.subSteps:
            steps.extend(self._flattenSubStep(subStep))
        return steps

    def _flattenSubStep(self, subStep: BuildStep) -> list[BuildStep]:
        details: list[BuildStep] = []
        no_sub_steps = deepcopy(subStep)
        no_sub_steps.subSteps = []
        details.append(no_sub_steps)
        for detail in subStep.subSteps:
            no_sub_steps = deepcopy(detail)
            no_sub_steps.subSteps = []
            details.append(no_sub_steps)
            if detail.subSteps:
                details.extend(detail.subSteps)
        return details


class BuildCategory(Enum):
    NOOP = "noop"
    CLEAN = "clean"
    INCREMENTAL = "incremental"


@dataclass
class BQRecord:
    start_time: float
    compilation_duration: float
    machine_name: str
    build_category: str
    scheme: str


def tweak_parse_result(data: JSON) -> JSON:
    """
    To prevent schema inconsistencies,
    unify the data types of the 'duration' like fields with float.
    """
    for k in data:
        if isinstance(data[k], list):
            for d in data[k]:
                if isinstance(d, dict):
                    tweak_parse_result(d)
        elif isinstance(data[k], dict):
            tweak_parse_result(data[k])
        elif "duration" in k.lower():
            data[k] = float(data[k])
    return data


def get_xclogparse_json() -> JSON:
    """
    Generate a JSON of XCLogParser's parse result
    """
    parse_output = subprocess.check_output(["make", "dump-xclogparser-json"])
    parse_result_json = json.loads(parse_output.decode("utf-8"))
    tweak_parse_result(parse_result_json)
    return parse_result_json


def parse_build_category(build_step: BuildStep) -> BuildCategory:
    """
    Determine whether the build is clean or incremental

    ref. https://github.com/spotify/XCMetrics/blob/main/Sources/XCMetricsBackendLib/UploadMetrics/LogProcessing/LogParser.swift
    """
    steps = build_step.flatten()
    detail_steps = [s for s in steps if s.type == "detail"]
    n_fetched_from_cache = len([s for s in detail_steps if s.fetchedFromCache])
    if n_fetched_from_cache == len(detail_steps):
        return BuildCategory.NOOP
    elif n_fetched_from_cache / len(detail_steps) > 0.5:
        return BuildCategory.INCREMENTAL
    else:
        return BuildCategory.CLEAN


def gen_bq_record(parse_result_json: JSON) -> BQRecord:
    """
    Generate data corresponding to BigQuery table record
    """
    build_step = BuildStep.from_dict(parse_result_json)
    build_category = parse_build_category(build_step)
    return BQRecord(
        build_step.startTimestamp,
        build_step.compilationDuration,
        build_step.machineName,
        build_category.value,
        build_step.schema,
    )


def upload_to_s3(json_path: pathlib.Path):
    """
    Upload the build metrics data to AWS S3
    """
    subprocess.run(
        [
            "envchain",
            "aws",
            "aws",
            "s3",
            "cp",
            str(json_path.absolute()),
            os.environ["S3_BUCKET"],
        ]
    )


def main():
    logger.info("💨 started")
    # Since Xcode will take a while to finish writing the log to the file,
    # ensuring build log file is created by waiting for a seconds
    time.sleep(3)
    os.environ["PATH"] += os.pathsep + "/opt/homebrew/bin"
    if not os.getenv("S3_BUCKET"):
        logger.warning("🙄 `S3_BUCKET` environment variable is not set...")
        return
    dir_path = os.path.dirname(os.path.realpath(__file__))
    prj_root_dir = os.path.join(dir_path, "..")
    os.chdir(prj_root_dir)

    with tempfile.TemporaryDirectory() as tmpdir:
        suffix = datetime.now().strftime("%Y-%m-%dT%H:%M:%S")
        fpath = pathlib.Path(tmpdir) / f"xclogparser_{suffix}.json"
        with open(fpath, "w") as tmpf:
            parsed_json = get_xclogparse_json()
            bq_record = gen_bq_record(parsed_json)
            tmpf.write(json.dumps(asdict(bq_record)))
        upload_to_s3(fpath)
    logger.info(
        "✅ successfully uploaded build metrics data:"
        f"{json.dumps(asdict(bq_record), indent=2)}"
    )
    logger.info("✔ finished")


if __name__ == "__main__":
    main()
    • ポイント2つ
      • a.) スキーマ不整合の回避
        • xclogparserによって抽出されたjsonのなかでビルド時間を表すdurationやcompilationDurationというフィールドがあり、通常はfloat値だがビルドキャッシュが存在する場合は0とint値になる場合がある
        • するとBQテーブルスキーマ不整合が起こり得る
        • ので、強制的にfloatでcastする処理を施している
      • b.) cleanビルドなのかincrementalビルドなのか判定
        • ビルド時間を観測する場合、clean/incrementalは明確に区別しておきたいというモチベーションがある
        • が、xclogparser結果には明示的に存在しない情報
        • 一方で、各ビルドstepでcache hitしているかどうかの情報はとれているので、この情報をつかって判定ロジックを書く
        • コードコメント記載のとおりここのロジックはXCMetricsを参考にさせていただいた(まったく同一ではなく端折っている)
        • XCMetrics実装では、「schemeをビルドするにあたりそれにぶら下がるBuild Targetsの内、半数以上がcache hitしているか」でclean判定している模様
        • 今回書いたのは「Bulid Targetを構成するdetail Build stepの内、半数以上がcache hitしているか」で判定しているかんじ
        • target単位でみるかソースファイル単位でみるかの違いで、実装がラクな方を選択(schemeの単位でみればcleanかincrementalかを判定するには十分と考えた)
          • target単位で細かくみる場合はまた違ってくるとおもう

S3とBigQuery側にデータの受け皿を用意

  • s3 bucket作成 
    $ aws s3 mb s3://xcbuildmetrics.example.com
  • BQ dataset作成 
    $ bq mk \
    --location=asia-northeast1 \
    --dataset {PROJECT_ID}:{DATASET}
  • BQ table作成 
    $ bq mk \
    --table \
    --time_partitioning_field start_time \
    --require_partition_filter \
    {PROJECT_ID}:{DATASET}.xcbuildmetrics \
    start_time:timestamp,compilation_duration:float,machine_name:string,build_category:string,scheme:string
    • image
  • BQ transfer_config(Data Transfer Service)作成 
    bq mk \
    --transfer_config \
    --project_id={PROJECT_ID} \
    --data_source=amazon_s3 \
    --display_name=transfer_xcbuildmetrics_data_from_s3 \
    --target_dataset={DATASET} \
    --params='{
    "data_path":"s3://xcbuildmetrics.example.com/",
    "destination_table_name_template":"xcbuildmetrics",
    "access_key_id":"xxx",
    "secret_access_key":"xxx",
    "file_format":"JSON"}'
    • データ転送が作成されると即時で実行される
      • image
    • データ転送が成功すると、こんなかんじでBQテーブルにデータが投入されている image

Data Portalで可視化する用のビューを作成する

Cleanビルドの時系列ビルド時間

SELECT
  start_time
  , compilation_duration
  , machine_name
  , build_category
  , scheme
FROM
  `{PROJECT_ID}.{DATASET}.xcbuildmetrics`
WHERE
  start_time >= TIMESTAMP("yyyy-mm-dd", "Asia/Tokyo")
  AND build_category = "clean"
ORDER BY
  start_time

Incrementalビルドの時系列ビルド時間

SELECT
  start_time
  , compilation_duration
  , machine_name
  , build_category
  , scheme
FROM
  `{PROJECT_ID}.{DATASET}.xcbuildmetrics`
WHERE
  start_time >= TIMESTAMP("yyyy-mm-dd", "Asia/Tokyo")
  AND build_category = "incremental"
  AND compilation_duration > 0
ORDER BY
  start_time

dailyのビルドstats

WITH
  daily_build_compilations AS (
    SELECT
      FORMAT_TIMESTAMP("%Y-%m-%d", start_time, "Asia/Tokyo") AS `date`
      , compilation_duration
    FROM
      `{PROJECT_ID}.{DATASET}.xcbuildmetrics`
    WHERE
      start_time >= TIMESTAMP("yyyy-mm-dd", "Asia/Tokyo")
    ORDER BY
      start_time
  )

SELECT
    PARSE_DATETIME("%Y-%m-%d", date) AS `date`
    , COUNT(*) AS num_builds
    , SUM(compilation_duration) AS total_compilation_duration
FROM
    daily_build_compilations
GROUP BY
    `date`
ORDER BY
    `date`

Data Portalで可視化する

作成したビューをデータソースとしてData Portalでグラフ化する

image
  • 「いつCleanビルドが行われビルド時間どれくらいかかったか」
  • 「いつIncrementalビルドが行われビルド時間どれくらいかかったか」
  • 「1日のトータルビルド実行回数」
  • 「1日のトータルビルド時間」

あたりをカンタンなクエリ書いて可視化できる

ログデータにはより詳細なtarget別ソースファイル別といった情報があるので、やろうとおもえばもっとspecificなdashboardがつくれそう(マルチモジュール構成なんかだと欲しそう)

まとめ

昨今の便利なツールとマネージドサービスのおかげで安価でサーバレスな構成でXcodeのビルド時間を監視するしくみはつくれる

参考