SQLを使ってログ解析をしよう

Hitoshi Harada

 

はじめに

システムを運用すると、日々のユーザのアクティビティがログという形で残っていくものです。ユーザの挙動を知ることはシステムを改善していく上で重要ですが、手間がかかると思ってなかなか手をつけられないのも現実でしょう。PostgreSQLに最近追加された機能の中にはログを解析する上で便利なものもたくさんありますので、これらをうまく使いながらログの解析をしてみたいと思います。

前提とするシステム

CentOS 5.4のLinux上にベータバージョンのPostgreSQL 9.0をインストールして実験します。一部の内容は9.0からですが、8.4やそれ以前から使える機能を多く紹介します。

使用するログ

今回、及び次回以降で使用するサンプルログはこちら (.zip) にあります。是非、記事を読みながらサンプルログを使って、手元のPostgreSQLで動作を確認してみて下さい。

シナリオ

今回のシナリオは、Webに公開された海外のホテルを検索するシステムのアクセスログです。ユーザはブラウザで検索画面にアクセスし、行き先の国・宿泊日などの条件を入力することで結果一覧を表示します。安い順や高い順で並べ替えて気に入ったホテルがあれば詳細画面へ遷移しますが、ここまでが検索システムの範囲です。

検索起動
↓
条件入力
↓　↑
結果一覧表示
↓
詳細画面へ
  • 検索を途中でやめてしまったユーザ（＝離脱）がどのぐらいいるのか
  • 離脱したユーザと詳細まで遷移したユーザで、どのような違いがあるのか
  • 詳細へ遷移したユーザはどのような検索行動を行っているのか

などの事象を調べることとします。

ログには千差万別あり、PostgreSQLのようなRDBMのSQLログもあれば、監視システムが定期的に出力するログもあります。今回解析するログは、検索システムとなるWebアプリケーションが出力するアクセスログです。WebのアクセスログといえばApacheのcombined形式が一般的だと思いますが、ここでの形式は独自形式のCSVで、下記のようなものです。

列No. 論理名 物理名 説明
1 セッションID sessionid 16進数のユニークブラウザID
2 アクセス時刻 atime YYYY-MM-DD HH24:MI:SS JST形式
3 シーケンス番号 seq ログの通し番号（自然数）
4 処理時間 elapse リクエスト処理時間（ミリ秒）
5 アクション名 action 処理名称
6 パラメータ文字列 params key1（タブ）value1（タブ）key2...形式

各項目がカンマ区切りのテキストで1行を構成します。実際には下記のような内容です。 (注)幅の関係で1行のデータを2行に分けて記述しています。

ee1bdfe5b017f8dcddea61b54aa76536,2010-05-13 00:00:03,1,277,DoSearch,sort
	安い順	region	ハワイ	country	ハワイ島
ee1bdfe5b017f8dcddea61b54aa76536,2010-05-13 00:00:04,2,115,ShowList,sort
	安い順	region	ハワイ	country	ハワイ島
ee1bdfe5b017f8dcddea61b54aa76536,2010-05-13 00:00:06,3,344,DoSearch,date
	20100701	sort	安い順	region	ハワイ	country	ハワイ島
ee1bdfe5b017f8dcddea61b54aa76536,2010-05-13 00:00:06,4,130,ShowList,date
	20100701	sort	安い順	region	ハワイ	country	ハワイ島
ee1bdfe5b017f8dcddea61b54aa76536,2010-05-13 00:00:30,5,292,DoSearch,date
	20100701	sort	安い順	region	ハワイ	country	ハワイ島
ee1bdfe5b017f8dcddea61b54aa76536,2010-05-13 00:00:30,6,117,ShowList,date
	20100701	sort	安い順	region	ハワイ	country	ハワイ島
5171a0d7e2bee655ba472f5e431cc9a7,2010-05-13 00:00:48,7,2,SearchStart,sort
	安い順
5171a0d7e2bee655ba472f5e431cc9a7,2010-05-13 00:00:50,8,204,DoSearch,sort
	安い順
5171a0d7e2bee655ba472f5e431cc9a7,2010-05-13 00:00:51,9,106,ShowList,sort
	安い順
d8ab78fc89ca454766d10b648b014438,2010-05-13 00:00:52,10,784,DoSearch,date
	20100527	sort	安い順	region	中国	country	香港
（続く...）

尚、アクションについては、下記のような意味を持っています。

  • SearchStart : 検索画面に最初に到達
  • DoSearch : 検索条件を入力
  • ShowList : 結果を一覧で表示
  • ShowDetail : 詳細画面へ遷移

このログのSQLでのテーブル定義は下記のようになります。

CREATE TABLE log_table(
  sessionid     char(32),
  atime         timestamp,
  seq           int,
  elapse        int,
  action        text,
  params        text
);

combined形式のログに比べて、セッション情報が記録されているため、ユーザの挙動を追いやすいログになっています。

COPYコマンドでログを取り込もう

まずはCSVからデータを取り込む処理です。他のRDBMでもCSVからデータを取り込む機能があると思いますが、PostgreSQLではCOPYというコマンドを使うと一括でCSVを取り込むことができます。

=# SET client_encoding TO sjis;
=# COPY log_table FROM '/var/log/access_log.csv' CSV NULL '';

ファイルシステムの/var/log/access_log.csvからCSV形式でlog_tableテーブルに一括で取り込む、という記述です。デフォルトではNULL値の表現は'\N'とすることになっていますが、ここでのログファイルではNULLが空文字で表現されていますので、NULL ''と指定しています。データベースクラスタはUTF8エンコーディングで作成しているため、取り込みファイルの文字コードを指定するためにSETコマンドを使っています。 COPYコマンドはPostgreSQLサーバのローカルファイルシステムに対して読込を行うので、ログファイルをサーバのファイルシステム上に保存してください。うっかりクライアント側で保存していると、

ERROR:  could not open file "/var/log/access_log.csv" 
        for reading: No such file or directory
★実際には1行のメッセージとなります。

というエラーが発生しますので注意してください。クライアント側で保持しているログファイルのロードには、\copyを使います。

ちなみにPostgreSQLのCOPYコマンドは非常に柔軟性が高く、CSVに限らず一定のルールに則ったデータファイルをテーブルに取り込むことが可能です。例えばCSVの次によく使われるTSV（タブ区切り）ならば、

COPY log_table FROM '/var/log/access_log.tsv' DELIMITER E'\t';

DELIMITERでタブ文字を指定したり、或いはパイプ（|）で結合されている場合も同様にDELIMITERで指定することができます。CSVでは通常引用文字としてダブルクオートが用いられますが、これも任意の1文字を指定することが可能です。さらに1行目をカラム名として読み飛ばすためのHEADERオプションも覚えておいて損はないでしょう。またテーブルの列が全て揃っていなくても、

COPY log_table(settionid, atime) FROM ...

と読み込みたいカラム名を限定することも可能です。

COPYの高速化

COPYコマンドはINSERTを行毎に発行するよりも断然高速です。ログのように大量のデータをロードするのは時間のかかる処理ですから、可能な限りCOPYを使いましょう。さらに下記のような点に注意するとより高速に動作します。

  • COPYと同一トランザクションでCREATE TABLEする
    • →先行書き込みログ（WAL）を出力しないため高速です。
  • インデックス（プライマリキー含む）はCOPYの後に付ける
    • テーブルにインデックスがあると、COPYで行を追加する度にインデックスを追加します。プライマリキーを含めてインデックスを張るのはCOPYによるロードが完了した後に行うべきです。
  • 外部キーを削除しておく
    • インデックスと同様に外部キーも後から付与した方が高速です。

大量データ投入時のチューニング

また、大量のデータを一括ロードする際の設定値として、下記のようなものに注意します。

  • maintenance_work_mem
    • COPYには効果がありませんが、インデックスと外部キーの速度向上に役立ちます。COPY後のCREATE INDEXの前などにSETコマンドで設定すると良いでしょう。バッチ中であれば接続数も限られているはずなので数百MB～などの大きめの値を設定します。最大で2GB未満（2097151KB）まで指定可能です。
  • checkpoint_segments
    • PostgreSQLが読み込んだデータを実際にディスクに書き出す（チェックポイント）回数が増えると、速度が低下します。checkpoint_segmentsを増やすことにより、チェックポイントの回数を抑えることができます。デフォルトは3ですが、COPYで大量ロードするためには小さいようなので、経験的には10～15をお奨めします。
  • archive_mode
    • 溜まったWALをアーカイブ領域に待避するかどうかを指定するパラメータですが、今回のようなケースではもともとCSVログファイルからのロードなので、WALがなくても困りません。offにすることをお奨めします。
  • fsync
    • データを実際にディスクに書き出すまで同期するかどうかのパラメータです。offにすると信頼性が下がり速度が向上しますが、今回のようなケースではoffにするのもよいと思います。

ログデータを使って実際に高速化の効果を試してみました。archive_modeをonからoffに、checkpoint_segmentsを3から15に、fsyncをonからoffにしたところCOPYの実行時間が3/4に短縮されました。さらにCREATE TABLEとCOPYを同一トランザクションにすることでWALを全く出力しない方法を取り入れると、最初の実行時間の約1/2まで時間が短縮されました。

一般に、OLTP系で更新処理が頻発するようなケースと今回のようなOLAP系の処理では求めるものが異なるため、チューニングの勘所も上記のように変わってきます。

データを確認しよう

それでは、正しく取り込まれたかどうか少し確認します。 (注)幅の関係で出力結果を2段に分けて記述しています。

SELECT count(*) FROM log_table;
 count  
--------
 176834
(1 row)

SELECT substr(sessionid, 1, 5), atime::time, action, params 
  FROM log_table ORDER BY sessionid, seq LIMIT 10;

 substr |  atime   |   action    |                
--------+----------+-------------+
 000ed  | 22:58:40 | SearchStart |
 000ed  | 22:58:41 | DoSearch    |
 000ed  | 22:58:41 | ShowList    |
 000ed  | 22:58:45 | DoSearch    |
 000ed  | 22:58:46 | ShowList    |
 000ed  | 22:58:47 | DoSearch    |
 000ed  | 22:58:48 | ShowList    |
 000ed  | 22:59:36 | DoSearch    |
 000ed  | 22:59:36 | ShowList    |
 000ed  | 22:59:49 | DoSearch    |

|                              params                        
+-----------------------------------------------------------------------
| sort 安い順 region アメリカ・カナダ
| sort 安い順 region アメリカ・カナダ
| sort 安い順 region アメリカ・カナダ
| sort 安い順 region アメリカ・カナダ country アメリカ
| sort 安い順 region アメリカ・カナダ country アメリカ
| city ラスベガス sort 安い順 region アメリカ・カナダ country アメリカ
| city ラスベガス sort 安い順 region アメリカ・カナダ country アメリカ
| city ラスベガス sort 安い順 region アメリカ・カナダ country アメリカ
| city ラスベガス sort 安い順 region アメリカ・カナダ country アメリカ
| city ラスベガス sort 安い順 region アメリカ・カナダ country アメリカ
(10 rows)

どうやら問題なさそうです。セッションIDが000ed...のユーザはアメリカ・カナダの地域から検索を始めて、国をアメリカ、都市をラスベガスと絞り込んで一覧を表示したことがわかります。このようなログであれば、目的の解析ができそうです。

これで生ログをテーブルに取り込めました。取り込みを通して、COPY文の紹介、バッチ時のチューニング等をご紹介しました。

(2010年8月2日 公開)
file
access_log.zip (2.1 MB)

ブックナビゲーション