2017.07.04

iOSアプリのログ収集とデータモニタリングについて

門脇裕

はじめに

はじめまして、レストランボードでフロントエンド(iOS・Web)開発を担当している門脇と申します!

現在レストランボードのiOSでは、アプリのパフォーマンスやユーザの操作時間などを計測し、問題のある部分を分析する取り組みをおこなっています。

本記事では上記取り組みを実現するまでに利用したツールや環境構成、ちょっとしたサンプルを紹介します。

背景と目的

アプリのパフォーマンス向上&劣化防止

レストランボードでは、新機能の開発や保守・運用をしながらも、パフォーマンス改善を求める要望が多く上がっていたこともあり、アプリのパフォーマンス向上とパフォーマンスの劣化防止の取り組みをしていこうとしていました。

しかし、パフォーマンスを測定する仕組みすらなかったため、どの部分に問題が潜んでいるのかは感覚値でしかわからない状態でした。

仮に問題を特定して改善させようとしても、改善されたのかが目に見えない状態だったので、パフォーマンス向上させたとは言い切れない場合があります。

そこで、アプリのパフォーマンスを測定する取り組みについては以前、Airレジの事例があったので参考にして、計測を開始しました。

ということで、アプリのパフォーマンスを劣化させないようにすることと、パフォーマンスに問題のある部分を特定し、改善することでパフォーマンスを向上させることを目的としてこの施策に取り組んでいます。

アプリ操作におけるUI/UX改善

一方、ユーザの操作(予約登録や席移動など)についても改善すべき部分はあると感じていました。

そのためには以下のような、「ユーザがどんな操作をおこなっているのか」について知る必要がありました。

操作完了までにどれくらいの時間がかかっているのか
操作完了までにどれくらいのタップ数を要するのか

その上で、我々が想定している操作とは異なる部分に着目／改善していこうと考え、パフォーマンス計測と同様にログの収集をおこなうことにしました。

しかしながら、ユーザがどんな操作をおこなっているかを知る方法としては、ユーザに実際に操作してもらい、ユーザビリティに関する様々な質問をおこなう方法(ヒアリング)もあると思います。

とはいえ、ヒアリングはコスト(時間、労力など)が高い、かつ一部のユーザの意見であるため、その意見が正しいかどうか不明であるという問題点があります。

また、ヒアリングをおこなってUI変更をしたとして、操作スピードが向上したとか、操作タップ数が減った、といった改善指標となりうるデータは再度ユーザに操作してもらって計測しなければなりません。

よって、これら所々の問題を解決し、UI/UX改善の実現と、改善後に操作スピードやタップ数などがどれだけ良くなったのかをモニタリングすることも、目的の1つとしています。

利用したツール等

TreasureData

Airレジでの事例の通り、スキーマレスかつiOSのSDKが存在するTreasureDataを導入しています。

Redash

収集したログから各種データを可視化するためにRedashを用いることにしました。

Redashは無償のOSSで、オンプレで稼働させることが可能であり設置も容易であること、SQLの記述によってデータが可視化できることなど、エンジニアフレンドリーである点に魅力を感じ採用しています。

ログ収集

パフォーマンス計測のログ

まず、パフォーマンス計測の例としてレストランボードで最も利用されている「スケジュールビュー」について紹介します。

スケジュールビューのパフォーマンスとは、「スケジュールビューの画面更新時間」を指し、定義としては「スケジュールビューへの画面遷移開始から画面上部のローディングが消えるまで」としています。

スケジュールビューはいくつかの画面から遷移することができるため、開始点は複数存在します。

終了点であるローディングが消える時のログは1箇所で収集しています。

下図は上記のログ収集を表現したものです。

reload_screen

ユーザの操作時間計測のログ

続いて、ユーザの操作時間における計測の例としてレストランボードで最も操作の多い「予約登録」を紹介します。

「予約登録の操作時間」の定義としては「予約登録画面が開いてから予約登録確認画面が閉じるまで」としています。

ただし、予約登録画面が開かれたとしてもユーザが操作を始めていなければ、正しく操作時間を収集することができません。

そのため、ユーザのファーストアクション(何かしらのボタンやテキストフィールドを押下する等)のログを収集します。

こちらも簡単ではありますが、下図にログ収集の流れを示します。

操作終了ログについては、予約登録が成功しない限りは送信されません。

reservation

これらのログから各種時間を可視化することで、問題の特定や我々が想定していなかった使われ方をしているなどの気付きが得られるので、次のデータ可視化で簡単に説明します。

データ可視化

Redashでのデータ可視化

収集したログから、Redashを使ってデータを可視化します。

TreasureDataにあるログは、まずRedshiftやRedashが立っているサーバのpostgresqlといったデータソースに流します。

そのデータソースからRedash上でクエリを投げるようにして、少しでもクエリ結果を早めに、かつTreasureDataへの負荷を削減します。

※ とはいえ、RedashはTreasureDataをデータソースとして扱うこともできるため、何かすぐ調べたいことがある時は直接クエリを投げることも可能です。

まずは収集したログから必要な情報を抜き出して、そこから開始〜終了の時間差分を収集するクエリを投げます。

例として、上記で紹介した「予約登録の操作時間」をヒストグラムにして算出してみます。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
WITH
  reservation_action_time_table AS (
    SELECT
      result_table.*
    FROM
      (SELECT
        grouped_table.*,
        (grouped_table.timestamp - grouped_table.start_timestamp) AS reservation_time, -- 予約登録開始〜終了までの時間を算出(今回は利用しない)
        (grouped_table.timestamp - grouped_table.first_action_timestamp) AS reservation_action_time -- 予約登録 '操作' 開始〜終了までの時間を算出
      FROM
        (SELECT
          MAX(CASE WHEN a.event = 'New.Start' THEN a.timestamp ELSE NULL END) -- 下のOVER句と合わせて、全データを店舗IDごとにまとめて分割し、timestamp順に並べたとき、'New.Finish'の2個前のログが'New.Start'である行を取得する。ただし、timestampがnullのものはスルーする(MAX関数を利用するとnullの行を除外することができる)
          OVER(PARTITION BY a.store_id ORDER BY a.timestamp ASC ROWS 2 PRECEDING) AS start_timestamp, -- 店舗IDごとに分割し、timestamp順に並べるクエリ
          MAX(CASE WHEN a.event = 'New.FirstAction' THEN a.timestamp ELSE NULL END) -- 上記クエリと同様で、こっちは1個前のログが'New.FirstAction'だったら取得する。
          OVER(PARTITION BY a.store_id ORDER BY a.timestamp ASC ROWS 1 PRECEDING) AS first_action_timestamp,
          a.*
        FROM
          user_actions AS a
        WHERE
          TO_TIMESTAMP(timestamp) AT TIME ZONE 'UTC' >= '2017-04-25 00:00:00' -- 日付型のカラムがなかったため秒数(timestamp)から日付を割り出して期間を絞る
          AND TO_TIMESTAMP(timestamp) AT TIME ZONE 'UTC' < '2017-05-09 00:00:00'
        ) AS grouped_table
      WHERE
        grouped_table.event = 'New.Finish'
      ) AS result_table
    WHERE
      result_table.start_timestamp IS NOT NULL
      AND result_table.first_action_timestamp IS NOT NULL
      AND reservation_action_time >= 3 -- 操作時間が3~600秒までの予約登録だけに絞る
      AND reservation_action_time < 600
    ORDER BY
      reservation_action_time
  )
-- 最もネストの深いクエリから見たほうがわかりやすい
-- ここでいう秒間とは、ヒストグラムの階級(クラス)に該当する
SELECT
  *,
  ROW_NUMBER() OVER(), -- 行数を表示する
  SUM(percentage) OVER (ROWS BETWEEN UNBOUNDED PRECEDING AND CURRENT ROW) AS total -- 最初の行から現在の行までの予約登録数の累計割合を算出(例: 0~1秒までの予約登録数の累計割合10%, 1~2秒までの予約登録数の累計割合30%)
FROM
  (SELECT
    *, ((histogram.reservation_nums / SUM(histogram.reservation_nums) OVER ()) * 100) AS percentage -- 全体の予約登録数に対する各秒間の予約登録数の割合を算出する(例: 0~1秒の予約登録数は全体の10%、1~2秒の予約登録数は全体の20%)
  FROM
    (SELECT
      time_range_from,
      time_range_to,
      COUNT(*) AS reservation_nums
    FROM
      (SELECT
        (target_class - 1) * class_width AS time_range_from, -- 各秒間の下限値
        target_class * class_width AS time_range_to -- 各秒間の上限値
      FROM
        (SELECT
          class_width,
          CEIL(reservation_action_time_table.reservation_action_time / class_width) AS target_class -- 予約登録操作時間を秒間の幅で割って小数点を切り捨てた秒間にカウントする(2.3秒だったら2~3秒の秒間にカウントする)
        FROM
          (SELECT
            CEIL(max_reservation_action_time / class_nums) AS class_width -- 予約登録操作時間の最大値を秒間数で割って秒間の幅を算出する
          FROM
            (SELECT
              MAX(reservation_action_time_table.reservation_action_time) AS max_reservation_action_time, -- 予約登録操作時間の最大値を取得
              600 AS class_nums -- 秒間数を600個にする(本来はここでスタージェスの公式から秒間幅を求めて秒間数を決定すべき)
            FROM
              reservation_action_time_table
            ) t0
          ) t1, reservation_action_time_table
        ) t2
      ) t3
    GROUP BY
      time_range_from, time_range_to
    ORDER BY
      time_range_from
    ) AS histogram
  ) as sum_table

大まかなクエリの流れとしては以下のようになっています。

ログが格納されているテーブルから特定の期間のログを取り出す
ユーザを一意に特定できるID(今回は店舗IDとします)をひとまとめに並べて分割し、同時にtimestamp順で並び替える
イベント名(event)が「予約登録完了ログ(New.Finish)」で、その行の1つ前が「操作開始ログ(New.FirstAction)」で、2つ前が「予約登録開始ログ(New.Start)」という並びになっているログだけに絞る
予約登録完了時間から操作開始時間の差分を出す
ノイズデータを弾いて(4で算出された時間が3~600秒のものだけにする)、予約登録操作時間の早い順に並べる
ヒストグラムの作成(秒間数の算出 -> 秒間幅の算出 -> 各秒間への予約登録操作の振り分け -> 各秒間の予約登録数の割合と累計割合算出)

WITH句の中身を簡単に図解すると下図のようになります。

query

また、クエリ下部の方はヒストグラムの算出クエリになります。

一般的なヒストグラムの算出方法をおこなうとグラフが見にくかったり、階級(クラス)幅の粒度が粗かったりするので調整はしてます(一般的なスタージェスの公式を使うと幅が大きくなりすぎて数十秒単位になる -> 1秒単位で見たかった)。

続いて、算出したデータを適切なグラフにして可視化します。

Redashではグラフ(円、棒、折れ線など)やワードクラウド、ピボットテーブルなどが作成できます。

今回の例ではグラフが適切なので棒グラフを作成してみます。

reservation_action_time_histogram

以上のようにして収集したログからデータ可視化することがサクッとできます。この他にも予約登録操作の平均時間などを計測しています。

データ分析

上記のようなデータを分析してみてわかったことがいくつかあるのですが、例えば以下のような仮説が導き出されます。

ほとんどの予約登録操作が数十秒で完了している

　　-> 電話をしながら数十秒で予約登録を完了させるには無理があるため、電話をしながら予約登録操作をおこなっているユーザは少ないのでは

　　-> 紙に1回メモをとってからアプリで予約登録しているのでムダが発生している可能性がある

この仮説から、「電話をしながらでもカンタンに予約登録操作ができるUIに変更する」といったアクションも考えられるかと思います。

その他に、パフォーマンス計測でも同じようにデータの可視化をしてみた結果、iPadの端末モデルによってパフォーマンスの差があることがわかったので(母数の差はありますが)、推奨・非推奨端末の選定に役立てることもできると考えています。

今までにはない発見が得られますし、継続的にデータ可視化をすることでデグレ検知もできるようになります。いいことだらけですね!

おわりに

簡単にではありますが、iOSに関するログの収集と、ログデータから見えるデータについて説明させて頂きました。

個人的にではありますが、データを元にプロダクトの問題を発見すること、プロダクトを改善していくことはどんなエンジニアにも必要なことだと考えています。

サーバのログだけでは見えてこない部分もあると思うので、一度試してみてはいかがでしょうか^^

それでは、失礼しました!

Recruit Tech Blog

タグから見つける