モバイル基盤グループのヴァンサン(@vincentisambart)です。
開発者がどれくらいアプリのビルドを待っているのか気になったことありませんか？計測してみたらおもしろいかもしれません。どうすれば Xcode でビルド時間を計測できるのでしょうか。
プロジェクトの Build Phases の一番上と一番下にスクリプトを入れたら、ある程度計測できそうですが、制限が多そうですね。失敗したビルドや途中で止められたビルドは計測できないし、ビルドのどういうところに時間が掛かったのか詳しく分かりません。
ビルド時に Xcode がログを取っているはずなので、ログの中に時間が入っていないかな…？
最初から複雑なプロジェクトで試すのは不便でしかないので、始める前に Xcode (現時点で 9.1 ) で新規のプロジェクト(例えば iOS の Single View App)を作って、いじらずに１〜２回ビルドします。以下の調査はそのビルドで生成されたファイルを見ます。
ビルドログの在り処
求めているデータが入っているのを確認するために、まずどこに保存されているのを探す必要があります。
既に知っている開発者が多いかと思いますが、 Xcode はビルド時に生成する殆どのファイルを ~/Library/Developer/Xcode/DerivedData/<アプリ名>-<ID> に入れます。そのディレクトリの中を見てみると、 Logs/Build にビルドログが入っていそうですね。最近ビルドされたプロジェクトの場合、そこに Cache.db というファイルと、拡張子が xcactivitylog のファイルが入っています。
因みに、ビルドログがビルド終了後に更新されるので、ビルドの途中は前のビルドのログしか見られないようです。
Cache.db
Cache.db の中身をエディターなどで見てみると、バイナリファイルではありますが、頭に bplist があります。バイナリ plist なのでは？ターミナルで plutil -p を使って中身を見てみましょう。
$ plutil -p Cache.db
{
"logs" => {
"4E46321A-9204-42C9-AC76-BF6F01B77E64" => {
"timeStartedRecording" => 532831205.501172
"timeStoppedRecording" => 532831210.725163
"domainType" => "Xcode.IDEActivityLogDomainType.BuildLog"
"title" => "Build BlogTest"
"signature" => "Build BlogTest"
"schemeIdentifier-schemeName" => "BlogTest"
"schemeIdentifier-containerName" => "BlogTest project"
"schemeIdentifier-sharedScheme" => 1
"documentTypeString" => "<nil>"
"highLevelStatus" => "S"
}
"A6D6AD38-4367-439C-8021-31156A579B81" => {
"timeStartedRecording" => 532831597.574763
"timeStoppedRecording" => 532831597.597417
"domainType" => "Xcode.IDEActivityLogDomainType.BuildLog"
"title" => "Build BlogTest"
"signature" => "Build BlogTest"
"schemeIdentifier-schemeName" => "BlogTest"
"schemeIdentifier-containerName" => "BlogTest project"
"schemeIdentifier-sharedScheme" => 1
"documentTypeString" => "<nil>"
"highLevelStatus" => "S"
}
}
"logFormatVersion" => 8
}
時間
timeStartedRecording と timeStoppedRecording が興味深いですね。 time という名前だけど、浮動小数点数のようですね。よく考えてみると、 Swift で Date を浮動小数点数から作成する方法が幾つかあります：
Date(timeIntervalSinceNow: TimeInterval)Date(timeIntervalSince1970: TimeInterval)Date(timeIntervalSinceReferenceDate: TimeInterval)
Date(timeIntervalSinceNow:) は呼ばれるタイミングによって結果が変わるので、違うはずですね。
全般的に、タイムスタンプは 1970 年からの秒数がよく使われるので、 Playground で試してみましょう。
Date(timeIntervalSince1970: 532831205.501172)
→ "Nov 20, 1986 at 9:40 AM"
ビルドしたばかりなので、 1986 年のはずがない(笑)
Date(timeIntervalSinceReferenceDate:) だとどうなるんだろう。
Date(timeIntervalSinceReferenceDate: 532831205.501172)
→ "Nov 20, 2017 at 9:40 AM"
お、丁度いい！実際ビルドにどれくらい掛かったのかは timeStoppedRecording に timeStartedRecording を引けば秒数が分かるので Date にする必要ないのですが(笑)
因みに、 timeIntervalSinceReferenceDate が Apple 独自のものだとはいえ、 Ruby でも簡単にできます。
APPLE_REFERENCE_DATE = Time.new(2001, 1, 1, 0, 0, 0, 0) # 2001/01/01 00:00:00 UTC def time_from_time_interval_since_reference_date(time_interval) APPLE_REFERENCE_DATE + time_interval end time_from_time_interval_since_reference_date(532831205.501172).getlocal # => 2017-11-20 09:40:05 +0900
他の項目
Cache.db の他の項目は分かりやすいものが多いですね。
logs に入っている GUID が同じディレクトリに入っている xcactivitylog ファイルのファイル名と一致しています。
logFormatVersion は Xcode のバージョンによるもののようです。 Xcode 8.3.3 が生成した Cache.db の logFormatVersion は 7 ですが、 Xcode 9.0~9.1 が生成したやつはlogFormatVersion が 8 です。でも logFormatVersion 7 も 8 も Cache.db の中身が同じのようです。
これでビルド時間が正確に分かります。ただし、詳細が分かりませんし、ビルドが成功したのかどうか分かりません。
xcactivitylog
もっと詳しくは xcactivitylog ファイルの中身を見る必要があるかもしれません。少しネットで調べてみたら、 xcactivitylog の中身が gzip で圧縮されているらしいことが分かりました。
でも gzip -cd で展開してみると、テキストファイルに見えなくもないが、変な文字が入っているし、改行がおかしいし、時間らしいものが見当たりません…一応ファイルの最後を見ると Build stopped- 、Build failed- 、 Build succeeded- でビルドの結果が分かります。ファイル名と Cache.db に入っている GUID が一致するので、情報を合わせるとビルド時間とビルド結果が分かりますけど、詳細がまだ…
トークン読込
ネットでもう少し調べてみたら Haskell で書かれた xcactivitylog を読み込むコードがありました。結局テキストファイルじゃなかった。
Haskell はよく分からないけど、 Haskell でのコードやそのコメントを見ながら、 xcactivitylog を Ruby スクリプトで読み込もうとして試行錯誤で分かった形式は以下の通りです。
まず、ファイルが SLF0 で始まって、その後はトークンのリストが並んでいるだけです。
トークンは以下の7種類のようです。
| 正規表現 | 種類 | 頭の数字が表しているもの |
|---|---|---|
- |
nil | |
[0-9]+# |
数字 | 値 |
[0-9]+" |
文字列 | 文字列の長さ |
[0-9]+\( |
リスト | リストに入っている項目の数 |
[0-9]+% |
クラス名 | クラス名の長さ |
[0-9]+@ |
オブジェクト | クラス名の番号(% で定義された最初のクラス名が 1 となる) |
[a-f0-9]{16}\^ |
浮動小数点数 | 16進法でメモリ上のリトルエンディアンの64-bitの浮動小数点数(double) |
では、 Ruby で読み込むスクリプトを書きましょう。まず gzip で圧縮されたデータを展開します。
require 'zlib' raise "Syntax: #{$0} file.xcactivitylog" unless ARGV.length == 1 file_path = ARGV[0] raw_data = Zlib::GzipReader.open(file_path, encoding: Encoding::BINARY) { |gzip| gzip.read }
その後、トークンを1個ずつ読み込みます。
require 'strscan' scanner = StringScanner.new(raw_data) # なぜか StringScanner に特定の文字数を読み込むメソッドはないので生やす def scanner.read(length) string = peek(length) self.pos += length string end raise 'Invalid format' unless scanner.scan(/SLF0/) class_names = [] tokens = [] while !scanner.eos? if scanner.scan(/([0-9]+)#/) # integer value = scanner[1].to_i # 頭の数字が値 tokens << { type: :int, value: value } elsif scanner.scan(/([0-9]+)%/) # class name length = scanner[1].to_i # 頭の数字がクラス名の長さ name = scanner.read(length) raise "Class name #{name} should not be present multiple times" if class_names.include?(name) class_names << name.to_sym elsif scanner.scan(/([0-9]+)@/) # object class_index = scanner[1].to_i # 頭の数字がクラスの番号(最初に定義されたクラスが 1) raise "Unknown class reference #{class_index} - Known classes are #{class_names.join(', ')}" if class_index > class_names.length tokens << { type: :object, class_name: class_names[class_index-1] } elsif scanner.scan(/([0-9]+)"/) # string length = scanner[1].to_i # 頭の数字が文字列の長さ string = scanner.read(length) tokens << { type: :string, value: string } elsif scanner.scan(/([0-9]+)\(/) # list # 頭の数字がリストの項目数 count = scanner[1].to_i tokens << { type: :list, count: count } elsif scanner.scan(/([a-f0-9]+)\^/) # double hexadecimal = scanner[1] # 16進法でメモリ上のリトルエンディアンのdouble # "cf4c80e55bc2bf41" -> ["cf", "4c", "80", "e5", "5b", "c2", "bf", "41"] characters_grouped_by_2 = hexadecimal.each_char.each_slice(2).map(&:join) # ["cf", "4c", "80", "e5", "5b", "c2", "bf", "41"] -> [207, 76, 128, 229, 91, 194, 191, 65] bytes = characters_grouped_by_2.map { |hex| hex.to_i(16) } # [207, 76, 128, 229, 91, 194, 191, 65] -> "\xCFL\x80\xE5[\xC2\xBFA" -> [532831205.501172] -> 532831205.501172 double = bytes.pack('C*').unpack('E').first tokens << { type: :double, value: double } elsif scanner.scan(/-/) # nil tokens << { type: :nil } else raise "unknown data #{scanner.peek(30).inspect}" end end require 'pp' pp tokens
シンプルなプロジェクトのビルドで生成された xcactivitylog ファイルを上記のスクリプトに読み込ませると以下のような出力が出ます。
[{:type=>:int, :value=>8},
{:type=>:object, :class_name=>:IDEActivityLogSection},
{:type=>:int, :value=>0},
{:type=>:string, :value=>"Xcode.IDEActivityLogDomainType.BuildLog"},
{:type=>:string, :value=>"Build BlogTest"},
{:type=>:string, :value=>"Build BlogTest"},
{:type=>:double, :value=>532831205.501172},
{:type=>:double, :value=>532831210.725163},
{:type=>:list, :count=>1},
{:type=>:object, :class_name=>:IDEActivityLogSection},
{:type=>:int, :value=>1},
{:type=>:string,
:value=>"Xcode.IDEActivityLogDomainType.target.product-type.tool"},
{:type=>:string, :value=>"Build target BlogTest"},
{:type=>:string, :value=>"BlogTest-ehwnkjvfrwpvqwdylenlszdndskk"},
{:type=>:double, :value=>532831205.611886},
{:type=>:double, :value=>532831210.71247},
{:type=>:list, :count=>7},
{:type=>:object, :class_name=>:IDEActivityLogSection},
{:type=>:int, :value=>2},
{:type=>:string, :value=>"com.apple.dt.IDE.BuildLogSection"},
{:type=>:string, :value=>"Check dependencies"},
{:type=>:string, :value=>"Check dependencies"},
{:type=>:double, :value=>532831205.611923},
{:type=>:double, :value=>532831205.613694},
{:type=>:nil},
{:type=>:nil},
{:type=>:nil},
{:type=>:int, :value=>0},
{:type=>:int, :value=>1},
{:type=>:int, :value=>0},
{:type=>:nil},
{:type=>:nil},
{:type=>:string, :value=>"Check dependencies"},
{:type=>:string, :value=>"E8680327-DEA4-4414-8A84-5FD0D3E2C765"},
{:type=>:nil},
{:type=>:nil},
{:type=>:object, :class_name=>:IDEActivityLogSection},
{:type=>:int, :value=>2},
{:type=>:string, :value=>"com.apple.dt.IDE.BuildLogSection"},
{:type=>:string, :value=>"Compile Swift source files"},
{:type=>:string,
:value=>"CompileSwiftSources normal x86_64 com.apple.xcode.tools.swift.compiler"},
{:type=>:double, :value=>532831205.61325},
{:type=>:double, :value=>532831209.491755},
{:type=>:list, :count=>2},
(略)
{:type=>:int, :value=>0},
{:type=>:int, :value=>0},
{:type=>:nil},
{:type=>:nil},
{:type=>:nil},
{:type=>:string, :value=>"4E46321A-9204-42C9-AC76-BF6F01B77E64"},
{:type=>:string, :value=>"Build succeeded"},
{:type=>:nil}]
もっと多くの情報が取れそう。でも上記のスクリプトと出力に不自然だと思われるところがあるかもしれません。なぜリストは作らずに項目数を取っておくだけ？オブジェクトはクラス名は分かるけど中身は？
実はオブジェクトトークンは「ここからこのクラスのオブジェクトが始まる」ことを表しています。オブジェクトの属性はその直後に来るいくつかトークンです。ただし属性の種類や数は分かりません。 Xcode はもちろん各クラスの属性を分かっているでしょうけど、僕らは色々調査してみるしかありません。
リストは入っているオブジェクトの属性の数が分からないと各オブジェクトがどこまでなのか分からないのでまだ作れません。
属性の種類や数は少し時間掛かるけどそこまで難しくありません。
ログバージョン
オブジェクトに入っている属性に集中する前に、まずファイルの最初のトークンを見ましょう。8。 Cache.db に入っていた logFormatVersion と同じ。偶然？ Xcode 8.3 でアプリをビルドしてみて、生成されたログでは、 Cache.db の logFormatVersion 同様 7 になります。やっぱり、 logFormatVersion でしょう。因みに、 xcactivitylog は見てみた限りでは、 7 と 8 で変わった部分が1ヶ所があります(具体的には IDEActivityLogSection の最後に項目が1つ追加された)。
分かりやすさのため、以下は Xcode 9 のログ形式バージョン 8 だけに集中します。
オブジェクトの属性を調査
属性はどうしましょう。試行錯誤するしかないですね。トークンのリストを見て仮説をたてて、その仮説を元にスクリプトを変えて、スクリプトをいくつかの xcactivitylog ファイルに処理させてみて、結果によって仮説とスクリプトを調整する、の繰り返しです。
トークンのリストを見ると、 IDEActivityLogSection がいつも以下のような項目で始まるようですね。その仮説を検証してみましょう。
{:type=>:object, :class_name=>:IDEActivityLogSection},
{:type=>:int, :value=>2},
{:type=>:string, :value=>"com.apple.dt.IDE.BuildLogSection"},
{:type=>:string, :value=>"Compile Swift source files"},
{:type=>:string,
:value=>"CompileSwiftSources normal x86_64 com.apple.xcode.tools.swift.compiler"},
{:type=>:double, :value=>532831205.61325},
{:type=>:double, :value=>532831209.491755},
{:type=>:list, :count=>2},
{:type=>:object, :class_name=>:IDEActivityLogSection},
仮説を検証するために、期待していない値がある時点ですぐ raise (例外発生)をしましょう。以前のスクリプトが出したトークンのリストを見れば属性の型はある程度分かるけど、名前は分からないので一旦 fieldXXX にします。 IDEActivityLogSection を幾つか見てみると7番目に入るリストは nil になることもあるようなのでそれに対応しました。最初からそれに気づかなくても問題ありません。実行したらエラーが出て、直して、また実行する、の繰り返しなので。あと開発中、コード内にデバッグ出力のため p や pp をよく使いますが、読む時はノイズになるので以下のコードではそれを省きました。また、このブログが長くなりすぎないように、細かい試行錯誤については省略しています。
class TokenReader def initialize(tokens) @tokens = tokens.dup end def tokens_left_count @tokens.length end def read(expected_type, args = {}) token = @tokens.shift return nil if token[:type] == :nil && args[:nullable] raise "Expecting token of type #{expected_type.inspect} but got #{token.inspect}" if token[:type] != expected_type case expected_type when :list expected_class_name = args[:class_name] (0...token[:count]).map { read(:object, class_name: expected_class_name) } when :object expected_class_name = args[:class_name] class_name = token[:class_name] raise "Expected an object of class #{expected_class_name} but got an instance of #{class_name}" if class_name != expected_class_name fields = { class_name: class_name } case class_name when 'IDEActivityLogSection' fields[:field1] = read(:int) fields[:field2] = read(:string) fields[:field3] = read(:string) fields[:field4] = read(:string) fields[:field5] = read(:double) fields[:field6] = read(:double) fields[:field7] = read(:list, nullable: true, class_name: :IDEActivityLogSection) else raise "Unknown class name #{class_name}" end fields else token[:value] end end end # tokens は上記のスクリプトで生成したもの reader = TokenReader.new(tokens) log_format_version = reader.read(:int) raise "Unknown log format version #{log_format_version}" if log_format_version != 8 pp reader.read(:object, class_name: :IDEActivityLogSection) p reader.tokens_left_count
実行してみたら Expecting token of type :object but got {:type=>:nil} と怒られました。スタックトレースを見ると、リストを読み込もうとしている時です。もう少し調査してみると、7つめの属性である IDEActivityLogSection のリストは1項目が無事に読み込まれたけど2項目目を読もうとしている時にエラーが起こります。リストの全項目が同じ型を想定していましたが、 IDEActivityLogSection の直後に nil が入っている。リストにオブジェクトに混ざって nil が入っていると考えにくいので、理由は別にありそうです。
リストの始めからエラーが起きた少しあとまでのトークンを見てみましょう。
{:type=>:list, :count=>7},
{:type=>:object, :class_name=>:IDEActivityLogSection},
{:type=>:int, :value=>2},
{:type=>:string, :value=>"com.apple.dt.IDE.BuildLogSection"},
{:type=>:string, :value=>"Check dependencies"},
{:type=>:string, :value=>"Check dependencies"},
{:type=>:double, :value=>532831205.611923},
{:type=>:double, :value=>532831205.613694},
{:type=>:nil},
{:type=>:nil},
{:type=>:nil},
{:type=>:int, :value=>0},
{:type=>:int, :value=>1},
{:type=>:int, :value=>0},
{:type=>:nil},
{:type=>:nil},
{:type=>:string, :value=>"Check dependencies"},
{:type=>:string, :value=>"E8680327-DEA4-4414-8A84-5FD0D3E2C765"},
{:type=>:nil},
{:type=>:nil},
{:type=>:object, :class_name=>:IDEActivityLogSection},
このリストには項目が7つもある。どの項目も IDEActivityLogSection の可能性が高い。なら少し下にある IDEActivityLogSection はリストの2項目目なのでは？別のオブジェクトの属性の可能性もありますが、まずそれで試してみましょう。
fields[:field1] = read(:int) fields[:field2] = read(:string) fields[:field3] = read(:string) fields[:field4] = read(:string) fields[:field5] = read(:double) fields[:field6] = read(:double) fields[:field7] = read(:list, nullable: true, class_name: :IDEActivityLogSection) fields[:field8] = read(:nil) fields[:field9] = read(:nil) fields[:field10] = read(:int) fields[:field11] = read(:int) fields[:field12] = read(:int) fields[:field13] = read(:nil) fields[:field14] = read(:nil) fields[:field15] = read(:string) fields[:field16] = read(:string) fields[:field17] = read(:nil) fields[:field18] = read(:nil)
また実行してみましょう。field14 を読み込もうとする時に以下のエラーが出ました。
Expecting token of type :nil but got {:type=>:object, :class_name=>:DVTDocumentLocation}
field14 が nil の場合もあれば、 DVTDocumentLocation のインスタンスの場合もあるようですね。
fields[:field14] = read(:object, nullable: true, class_name: DVTDocumentLocation)
DVTDocumentLocation の中身も探る必要がありますね。
{:type=>:object, :class_name=>:DVTDocumentLocation},
{:type=>:string,
:value=>
"file:///Users/vincent-isambart/Desktop/BlogTest/BlogTest/main.swift"},
{:type=>:double, :value=>0.0},
{:type=>:string,
:value=>"CompileSwift normal x86_64 (略)"},
{:type=>:string, :value=>"1D50F5EA-D2D1-4F45-9017-8D2CEFE85CBC"},
(略)
{:type=>:object, :class_name=>:DVTDocumentLocation},
{:type=>:string,
:value=>"file:///Users/vincent-isambart/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/Objects-normal/x86_64/BlogTest.swiftmodule"},
{:type=>:double, :value=>140736883871744.0},
{:type=>:string,
:value=>"MergeSwiftModule normal x86_64 (略)"},
{:type=>:string, :value=>"D19441A3-B3BE-4814-B29D-173A5F24F876"},
DVTDocumentLocation の属性はどこまででしょうか。ログファイル全体のトークンのリストを見て、ヒントになりそうなところを探しましょう。 IDEActivityLogSection の field14 が nil の場合がありますね。その時、直後の field15 と field16 が以下の通りだったところがあります。
{:type=>:string, :value=>"Check dependencies"},
{:type=>:string, :value=>"E8680327-DEA4-4414-8A84-5FD0D3E2C765"},
DVTDocumentLocation の属性が2つだったらうまくいきそうです。それでやってみましょう。
when :DVTDocumentLocation fields[:field1] = read(:string) fields[:field2] = read(:double)
その後出ていた nullable 関連のエラーをちょこっと直したら、テストで使っていたすごくシンプルなプロジェクトのビルドログが無事に解析できました。オブジェクトの属性の読込が以下のようになりました。
case class_name when :IDEActivityLogSection fields[:field1] = read(:int) fields[:field2] = read(:string) fields[:field3] = read(:string) fields[:field4] = read(:string) fields[:field5] = read(:double) fields[:field6] = read(:double) fields[:field7] = read(:list, nullable: true, class_name: :IDEActivityLogSection) fields[:field8] = read(:nil) fields[:field9] = read(:nil) fields[:field10] = read(:int) fields[:field11] = read(:int) fields[:field12] = read(:int) fields[:field13] = read(:string, nullable: true) fields[:field14] = read(:object, nullable: true, class_name: :DVTDocumentLocation) fields[:field15] = read(:string, nullable: true) fields[:field16] = read(:string) fields[:field17] = read(:string, nullable: true) fields[:field18] = read(:nil) when :DVTDocumentLocation fields[:field1] = read(:string) fields[:field2] = read(:double) else raise "Unknown class name #{class_name}" end
IDEActivityLogSection を読み込んだあとに残っているトークンを見ようとしたら、トークンが残っていないので、ファイルに入っているのはログバージョンと1つの IDEActivityLogSection だけのようですね。もちろんその IDEActivityLogSection には色々入っています。
もう少し複雑なビルドログで同じことを繰り返したら、こんな感じになりました。
命名
オブジェクトを読み込めたのはいいのですが、オブジェクトに入っている属性に名前がまだありません。どう付ければいいのでしょうか。
まず、 IDEActivityLogSection に入っている2つの double に簡単に名前を付けられます。最初に読み込もうとした xcactivitylog ファイルでは最初の2つ double が 532831205.501172 と 532831210.725163 でした。見た覚えあるような…そう、 Cache.db に入っていた timeStartedRecording と timeStoppedRecording と同じ値なので、 Cache.db に入っていた名前を使えばいいです。
同様、 Cache.db の中身と比べて domainType 、 title 、 signature も分かります(title と signature は値が同じなのでどっちがどっちか逆になってしまうかもしれませんが)。
あとはクラス名や値自体を元に名前を付けてみましょう。何もないよりマシです。DVTDocumentLocation の最初の項目が file:///Users/... で始まる文字列なので名前は url で良さそう。 DVTDocumentLocation が入る属性は location でいいんじゃないかな。 IDEClangDiagnosticActivityLogMessage や IDEActivityLogMessage のリストは messages でいかが。
一部の項目に名前を付けたスクリプトのバージョンがこちらで見られます。因みにログバージョン 7 にも対応しています。
もっと多くの属性に名前を付けるには方法が色々ありそうです。例えば意図的にビルドログに影響ありそうなもの(ビルド結果、警告、エラー)を変えて、何が変わったのかを見て名前を付けられそうですね。僕は目的がビルド時間だけだったのでそこまでやっていませんが。
名前を付けているスクリプトをシンプルなログに実行すると以下のような出力が出ます。読みやすさのためにクラス名、 nil な値、各 Swift ファイルのビルド詳細、を省いておきました。各ステップにどれくらい時間が掛かったのかがよく分かります。
{:domain_type=>"Xcode.IDEActivityLogDomainType.BuildLog",
:title=>"Build BlogTest",
:signature=>"Build BlogTest",
:time_started_recording=>532831205.501172,
:time_stopped_recording=>532831210.725163,
:result=>"Build succeeded",
:subsections=>
[{:domain_type=>"Xcode.IDEActivityLogDomainType.target.product-type.tool",
:title=>"Build target BlogTest",
:signature=>"BlogTest-ehwnkjvfrwpvqwdylenlszdndskk",
:time_started_recording=>532831205.611886,
:time_stopped_recording=>532831210.71247,
:subsections=>
[{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Check dependencies",
:signature=>"Check dependencies",
:time_started_recording=>532831205.611923,
:time_stopped_recording=>532831205.613694},
{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Compile Swift source files",
:signature=>"CompileSwiftSources normal x86_64 com.apple.xcode.tools.swift.compiler",
:time_started_recording=>532831205.61325,
:time_stopped_recording=>532831209.491755,
:subsections=>[(略)]
:location=>{:url=>"file:///Users/user-name/Desktop/BlogTest/BlogTest/main.swift"}},
{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Copy /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/DerivedSources/BlogTest-Swift.h",
:signature=>"Ditto /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/DerivedSources/BlogTest-Swift.h /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/Objects-normal/x86_64/BlogTest-Swift.h",
:time_started_recording=>532831209.492459,
:time_stopped_recording=>532831209.500314,
:location=>{:url=>"file:///Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/DerivedSources/BlogTest-Swift.h"}},
{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Link /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest",
:signature=>"Ld /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest normal x86_64",
:time_started_recording=>532831209.500942,
:time_stopped_recording=>532831210.568323},
{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Copy /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest.swiftmodule/x86_64.swiftdoc",
:signature=>"Ditto /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest.swiftmodule/x86_64.swiftdoc /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/Objects-normal/x86_64/BlogTest.swiftdoc",
:time_started_recording=>532831209.50099,
:time_stopped_recording=>532831209.507525,
:location=>{:url=>"file:///Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest.swiftmodule/x86_64.swiftdoc"}},
{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Copy /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest.swiftmodule/x86_64.swiftmodule",
:signature=>"Ditto /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest.swiftmodule/x86_64.swiftmodule /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Intermediates.noindex/BlogTest.build/Debug/BlogTest.build/Objects-normal/x86_64/BlogTest.swiftmodule",
:time_started_recording=>532831209.50093,
:time_stopped_recording=>532831209.507456,
:location=>{:url=>"file:///Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest.swiftmodule/x86_64.swiftmodule"}},
{:domain_type=>"com.apple.dt.IDE.BuildLogSection",
:title=>"Sign /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest",
:signature=>"CodeSign /Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest",
:time_started_recording=>532831210.571077,
:time_stopped_recording=>532831210.711349,
:location=>{:url=>"file:///Users/user-name/Library/Developer/Xcode/DerivedData/BlogTest-ehwnkjvfrwpvqwdylenlszdndskk/Build/Products/Debug/BlogTest"}}]}]}
集計
ログファイルを読み込めたのは良いけど、それでどうやって開発者のビルド時間を集計できるのでしょうか。僕はプロジェクトの Build Phases で Xcode にスクリプトを実行させています。スクリプトがまだ処理されていないログファイルから必要なデータだけを抽出してサーバーに送ります。ビルドが終わるまでログファイルが生成されないので、データは1個前のビルドになりますが、実行された日時が入っているのでデータが少し遅れて送られれても問題ありません。
この仕組は制限が色々あります。1個前のビルドログなので、処理が走る前にログが削除されたらデータがなくなります。 DerivedData 内のデータを自分で消さなくても、例えば別のログバージョンを使う Xcode で同じプロジェクトを開くとビルドログが全部削除されるようです。
でもビルド時間の計測が完璧じゃなくていいのではないでしょうか。
まとめ
どうやって Xcode のビルド時間を計測できるのか考えてみたら、 Xcode のログファイルからできないのか試してみました。結果的にビルドの各ステップの時間まで取得できるようになりました。
弊社では、集計されたビルド時間をグラフ化して、開発者が毎日どれくらいビルドを待っているのか、何回ビルドを実行しているのか、ビルドに平均でどれくらい時間が掛かるのか、が見えるようにしています。
そのデータでビルド時間短縮の必要性を証明できるようになったと思います。
