こんにちは。キャスレーコンサルティング IT部 松本です。
今回は、PostgreSQLで実行されたクエリからバグを探してみます。
目次
0.環境
PostgreSQL9.6
windows10
1．クエリの探し方(設定)
クエリを探すには、まず実行されたクエリが格納されている場所を知る必要があります。
PostgreSQLの場合は、設定ファイルで設定することでlogファイルに出力できるそうです。
postgreSQLマニュアル
ちなみにOracleの場合は、動的パフォーマンス(V$)・ビューからV$SQLなどで、取得することが出来ます。
それでは実際に設定をしていきます。
設定ファイル(postgresql.conf)はデフォルトであれば、「C:\Program Files\PostgreSQL\9.4\data」直下にあります。
念のため先にバックアップを取ってから以下の修正を行いましょう。
【修正1】
log_destination = ‘stderr’
ログをどこに出力するのかを設定します。
stderrと設定した場合、標準エラー出力として出力されます。
またこのほかに、syslogやcsvlogも設定が可能できます (‘syslog,stderr’ といった複数指定も可能です)。
【修正2】
logging_collector = on
修正1のlog_destinationでの出力を、ファイルに出力するようにする設定です。
【修正3】
log_statement = ‘all’
どのSQL文をログに記録するかを制御します。
有効な値は、none（off）、ddl、mod、およびall（全てのメッセージ）です。
ddlは、CREATE、ALTER、およびDROP文といった、データ定義文を全てログに記録します。
modは、全てのddl文に加え、INSERT、UPDATE、DELETE、TRUNCATE、およびCOPY FROMと
いった、データ変更文をログに記録します。
PREPAREとEXPLAIN ANALYZEコマンドも、そこに含まれるコマンドが適切な種類であればログが録られ
ます。拡張問い合わせプロトコルを使用するクライアントでは、Executeメッセージを受け取った時に
Bindパラメータの値が（すべての単一引用符が二重にされた常態で）含まれていた場合、ログに記録
されます。
【おまけ】
log_directory
logging_collectorを有効と設定した場合、ログファイルが作成されるディレクトリを設定します。
log_filename
logging_collectorが有効な場合、作成されたログファイルのファイル名を設定します。
2.使い方事例
事例のために以下のデータを用意します。
postgres=# select * from MEMBER;
id | name | age
——+——————+—–
001 | キャスレー太郎1 | 11
002 | キャスレー太郎2 | 12
003 | キャスレー太郎3 | 13
004 | キャスレー太郎4 | 14
005 | キャスレー太郎5 | 15
006 | キャスレー太郎6 | 16
007 | キャスレー太郎7 | 17
008 | キャスレー太郎8 | 18
009 | キャスレー太郎9 | 19
010 | キャスレー太郎10 | 20
(10 行)
まずは静的SQLがログに出力されるかを確認します。
以下でバッチから実際に実行されたクエリを確認し、バグの箇所を見つけてみます。
【バッチ説明】
13歳以下のメンバーを取得するSQLを実行するバッチ
【ディレクトリ構成】
C:\work\StaticSqlLogSample.bat
C:\work\sql\SELECT_STATIC_MEMBER.sql
【バッチ】
StaticSqlLogSample.bat
@echo off
setlocal enabledelayedexpansion
cd %~dp0
psql -f sql/SELECT_STATIC_MEMBER.sql -U postgres -d postgres
SELECT_STATIC_MEMBER.sql
select ‘静的SQL実行’;
select * from MEMBER WHERE AGE < 15;
【実行】
コマンドプロンプト起動
『C:\work>C:\work\StaticSqlLogSample.bat』を実行
【実行結果】
?column?
————-
静的SQL実行
(1 行)
id | name | age
——+—————–+—–
001 | キャスレー太郎1 | 11
002 | キャスレー太郎2 | 12
003 | キャスレー太郎3 | 13
004 | キャスレー太郎4 | 14
(4 行)
上記実行結果を確認すると、14歳のメンバーも取れてしまいました。
通常の手順であれば原因を確認するためにSQLを確認するかとは思いますが、
今回はログを見てみましょう。
C:\Program Files\PostgreSQL\9.4\data\pg_log\postgresql-2019-04-28_104204.log
2019-04-28 10:42:04 JST LOG: データベースシステムは 2019-04-28 10:41:45 JST にシャットダウンしました
2019-04-28 10:42:04 JST LOG: MultiXact member wraparound protections are now enabled
2019-04-28 10:42:04 JST LOG: データベースシステムの接続受付準備が整いました。
2019-04-28 10:42:04 JST LOG: 自動バキュームランチャプロセス
2019-04-28 15:04:02 JST LOG: 文: select ‘静的SQL実行’;
2019-04-28 15:04:02 JST LOG: 文: select * from MEMBER WHERE AGE < 15;
上記赤文字部に実行されたクエリが出力されており、条件の値が15歳になっていることが原因だとわかりました。静的SQLであれば、上記の様にログを見て確認をしなくとも、直接SQLを確認すればわかります。
では次に、動的SQLで実行してみます。
【バッチ説明】
静的SQL時と同様に13歳以下のメンバーを取得するSQLを実行するバッチです。
【ディレクトリ構成】
C:\work\DynamicSqlLogSample.bat
C:\work\sql\SELECT_DYNAMIC_MEMBER.sql
【バッチ】
C:\work\DynamicSqlLogSample.bat
@echo off
setlocal enabledelayedexpansion
cd %~dp0
set vc_table_name=”MEMBER”
set vc_age=15
psql -f sql/SELECT_DYNAMIC_MEMBER.sql -v TABLE_NAME=%vc_table_name% -v AGE=%vc_age% -U postgres -d postgres
SELECT_DYNAMIC_MEMBER.sql
select ‘動的SQL実行’;
select * from :TABLE_NAME WHERE AGE < :AGE;
【実行】
コマンドプロンプト起動
『C:\work>C:\work\DynamicSqlLogSample.bat』を実行
【実行結果】
?column?
————-
動的SQL実行
(1 行)
id | name | age
——+—————–+—–
001 | キャスレー太郎1 | 11
002 | キャスレー太郎2 | 12
003 | キャスレー太郎3 | 13
004 | キャスレー太郎4 | 14
(4 行)
こちらも結果を確認すると、14歳のメンバーが取れてしまいました。
静的SQLであればSQLファイルを確認すればよかったのですが、動的SQLなのでSQLファイルを見ても原因がわからない場合があります。
そういう場合に、ログを見てみましょう。
C:\Program Files\PostgreSQL\9.4\data\pg_log\postgresql-2019-04-28_104204.log
2019-04-28 15:34:46 JST LOG: 文: select ‘動的SQL実行’;
2019-04-28 15:34:46 JST LOG: 文: select * from MEMBER WHERE AGE < 15;
上記赤文字部に実行されたクエリが出力されており、条件の値が15歳になっていることが原因だとわかりました。
3.まとめ
・confファイルの設定で実行されたクエリをファイルに出力することが出来る。
・デバッグ等の際に使用することで、バグの原因調査が円滑に進められる可能性がある。
・出力先や設定等は異なる(ファイルにであったり、テーブルにであったり)が、
postgreSQL,Oracle,MySQL,SQLServer等のDBでは出力ができる。
最後までお読みいただき、ありがとうございました。
