クエリ統計情報ログ
クエリ統計情報ログ(Query statistics log)には、合計実行時間、合計処理時間、合計待ち時間、バックグラウンド処理と待ち時間などのクエリ実行統計に関するすべての情報が含まれています。
これは、クエリの実行に必要な総時間を記録し、実行速度の遅いクエリを特定するのに役立ちます。
実行速度の遅いクエリの原因を特定することで、TDV環境のパフォーマンスチューニングに役立てることができます。
クエリ統計情報ログ出力の有効化
デフォルトではクエリ統計情報ログの出力が無効となっています。有効化するには以下の手順に従います。
- TDV Studioを開く
- メニューバーの「管理」から「構成」を開き、検索窓に enable logging と入力する
Server > SQL Engine > Logging > Query Statistics Logging > Enable Logging
の値を INFO に変更する- 「適用」→「OK」をクリック
適用後、<TDVインストール先フォルダ>/logs
に statistics.N
(Nは0,1, ... の連番)のファイル名でログが出力されます。ログファイルのローテーション数は Server>SQL Engine>Logging>Query Statistics Logging>Rollover Limit
の値から変更可能です(デフォルトは3)。
ログの例
出力されるログの例は下記の通りです。
timestamp,query_id,user_id,type,datasource_id,status,row_count,total_time,proc_time,wait_time,bg_total_time,bg_proc_time,sql
2021--09-15 08:33:59.820 +0000,703601,-1973,SCAN,/system/datasources/repository,[NULL],0,0,0,-1,-1,-1,"SELECT ""fkeys"".""pk_catalog_name"" AS ""PKTABLE_CAT"",""fkeys"".""pk_schema_name"" AS ""PKTABLE_SCHEM"",""fkeys"".""pk_table_name"" AS ""PKTABLE_NAME"",""fkeys"".""pk_column_name"" AS ""PKCOLUMN_NAME"",""fkeys"".""fk_catalog_name"" AS ""FKTABLE_CAT"",""fkeys"".""fk_schema_name"" AS ""FKTABLE_SCHEM"",""fkeys"".""fk_table_name"" AS ""FKTABLE_NAME"",""fkeys"".""fk_column_name"" AS ""FKCOLUMN_NAME"",""fkeys"".""ordinal_position"" AS ""KEY_SEQ"",CAST(3 AS SMALLINT) AS ""UPDATE_RULE"",""fkeys"".""fk_name"" AS ""FK_NAME"",""fkeys"".""pk_name"" AS ""PK_NAME"",CAST(5 AS SMALLINT) AS ""DEFERRABILITY"" FROM ""tdvrepo"".""system_foreign_keys"" ""fkeys"" INNER JOIN ""tdvrepo"".""system_datasources"" ""datasources"" ON ""datasources"".""parent_path"" LIKE '/services/databases%' AND ""fkeys"".""fk_table_name"" = 'test_raw' AND ""fkeys"".""fk_schema_name"" = 'mysql57eks' AND ""fkeys"".""fk_catalog_name"" = 'mysql' AND ""fkeys"".""pk_table_id"" <> 0 AND 78983 = CAST(""fkeys"".""fk_datasource_id"" AS INTEGER) AND ""fkeys"".""fk_datasource_id"" = ""datasources"".""datasource_id"" ORDER BY CAST(""fkeys"".""fk_datasource_id"" AS INTEGER),""PKTABLE_CAT"",""PKTABLE_SCHEM"",""PKTABLE_NAME"",""KEY_SEQ"""
2021--09-15 08:34:35.170 +0000,703602,-1973,QUERY,[NULL],SUCCESS,151,53000000,52555072,-1,-1,-1,update oracle.oracle.order_detail_dev set STATUS = 'A' where ITEM_ID = '2100-10001
2021--09-15 08:34:49.940 +0000,703603,-1973,QUERY,[NULL],SUCCESS,3,40000000,16699968,-1,-1,-1,"SELECT{option parallel=1,case_sensitive,ignore_trailing_spaces=""false""} catalog_name AS TABLE_CAT, schema_name AS TABLE_SCHEM, table_name AS TABLE_NAME, table_type AS TABLE_TYPE, annotation AS REMARKS, cast(null as VARCHAR) AS TYPE_CAT, cast(null as VARCHAR) AS TYPE_SCHEM, cast(null as VARCHAR) AS TYPE_NAME, cast(null as VARCHAR) AS SELF_REFERENCING_COL_NAME, cast(null as VARCHAR) AS REF_GENERATION , table_creation_timestamp AS TABLE_CREATION_TIMESTAMP, table_modification_timestamp AS TABLE_MODIFICATION_TIMESTAMP FROM /services/databases/system/ALL_TABLES WHERE datasource_id=78983 AND catalog_name='japan_data' AND schema_name='jpn' AND table_name LIKE '%' ESCAPE '\' ORDER BY datasource_id, TABLE_CAT, TABLE_SCHEM, TABLE_TYPE, TABLE_NAME"
2021--09-15 08:34:49.940 +0000,703603,-1973,SCAN,/system/datasources/repository,[NULL],3,0,0,-1,-1,-1,"SELECT ""tables"".""catalog_name"" AS ""CATALOG_NAME"",""tables"".""schema_name"" AS ""SCHEMA_NAME"",""tables"".""table_name"" AS ""TABLE_NAME"",CASE WHEN ""tables"".""datasource_name"" = 'system' THEN ""annotations"".""annotation"" ELSE ""tables"".""annotation"" END AS ""ANNOTATION"",""tables"".""table_creation_timestamp"" AS ""TABLE_CREATION_TIMESTAMP"",""tables"".""table_modification_timestamp"" AS ""TABLE_MODIFICATION_TIMESTAMP"",""tables"".""datasource_id"" AS ""DATASOURCE_ID"",""tables"".""datasource_name"" AS ""DATASOURCE_NAME"" FROM (""tdvrepo"".""system_tables"" ""tables"" LEFT OUTER JOIN ""tdvrepo"".""system_annotations"" ""annotations"" ON 'en' = ""annotations"".""locale"" AND ""tables"".""table_name"" = ""annotations"".""annotation_name"" AND ""tables"".""table_id"" = ""annotations"".""annotation_id"") INNER JOIN ""tdvrepo"".""system_datasources"" ""datasources"" ON ""tables"".""table_name"" LIKE '%' ESCAPE '\' AND ""tables"".""schema_name"" = 'jpn' AND ""tables"".""catalog_name"" = 'japan_data' AND ""tables"".""datasource_id"" = 78983 AND ""datasources"".""parent_path"" LIKE '/services/databases%' AND 78983 = ""datasources"".""datasource_id"" AND ""tables"".""datasource_id"" = ""datasources"".""datasource_id"""
2021--09-15 08:34:49.940 +0000,703603,-1973,SCAN,System,[NULL],0,0,0,-1,-1,-1,/system/datasources/system/SYS_TRANSIENT_TABLES
各カラムの説明
ログファイルはカテゴリ別に","(カンマ)区切りにて各要素が記録されます。
1行目に出力される主なカラム名の名称と内容については以下の通りです。
カラム名 | 内容 |
timestamp | クエリ統計情報が生成された日時 |
query_id | クエリのID (Studioから参照できる「マネージャ」→"REQUESTS"のREQUEST IDと一致します) |
user_id | 実行したユーザID |
type |
クエリのタイプ QUERY/SCAN/PROCEDUREなど |
datasource_id | データソースID デフォルトはNULL |
status | クエリの状態 SUCCESS/FAILED/CANCELLEDのいずれかが入る |
row_count | クエリ実行時に処理された行数 |
total_time | クエリ終了までに要した時間(データ送受信にかかる時間+proc_time) |
proc_time |
クエリ処理に要した時間 |
wait_time |
他のクエリセットを実行するために、クエリを停止するのに必要なインターバル時間 |
bg_total_time | バックグラウンドで実行されたクエリのtotal_time |
bg_proc_time | バックグラウンドで実行されたクエリのproc_time |
sql |
実行されたクエリの内容 |
typeについて
typeに入る QUERY / SCAN / PROCEDUREについてはそれぞれ以下を意味します。
- QUERY: TDVサーバで発行されたクエリ
- SCAN: データソース内で実際に処理されたクエリ
- PROCEDURE: プロシージャ(SQLスクリプト、パラメータ化クエリ)
バックグラウンドタスクについて
通常、SQLスクリプトを実行する際には、バックグラウンドタスクが使用されることがあります。
これは、プロシージャの主ステートメントを実行中に、これとは別に別のタスクが実行される場合に発生します。
システム・タスクであったり、他のプロシージャやAPIを実行するための呼び出しであったりと、様々です。
クエリ統計情報ログのローテーションポリシーについて
クエリ統計情報ログのローテーションポリシーを変更する場合はServer > SQL Engine > Logging > Query Statistics Logging
にある各種パラメータを変更します。
パラメータ | 説明 |
Maximum Number of Logged Purged Requests | パージされたリクエストの統計情報を保存するために保持されるファイルの最大数。この数に達すると、ローテーションごとに最も古いファイルが削除されます。 この設定はFile Rotation Policyが 1 または 2 の場合にのみ有効です。 |
File Rotation Policy |
ログファイルがローテーションされる条件の設定です。 0: ある制限時間に達すると、ログファイルはローテートされ、新しいログファイルが作成されます。 |
File Time Type |
ログファイルのローテーションのタイミングの設定です。 0: 1時間ごとにローテーション。 |
Maximum Log File Row Count |
ログファイルの最大行数です。最大行数に達すると現在のログファイルはローテートされます。 この設定はFile Rotation Policyが2の場合のみ有効です。 |
Maximum Log File Size | ログファイルサイズの最大値です。最大値に達すると現在のログファイルはローテートされます。 0を設定した場合、ログファイルサイズは無制限に増加し、ローテーションされません。 この設定は、File Rotation Policyが1の場合のみ有効です。 |
Rollover Limit |
アクティブなものを含め、ローテーションで保持されるログファイルの最大数です。 この数に達すると、ローテーションごとに最も古いファイルが削除されます。 |