クエリ統計情報のログを出力する

クエリ統計情報ログ

クエリ統計情報ログ（Query statistics log）には、合計実行時間、合計処理時間、合計待ち時間、バックグラウンド処理と待ち時間などのクエリ実行統計に関するすべての情報が含まれています。
これは、クエリの実行に必要な総時間を記録し、実行速度の遅いクエリを特定するのに役立ちます。
実行速度の遅いクエリの原因を特定することで、TDV環境のパフォーマンスチューニングに役立てることができます。

クエリ統計情報ログ出力の有効化

デフォルトではクエリ統計情報ログの出力が無効となっています。有効化するには以下の手順に従います。

1. TDV Studioを開く
2. メニューバーの「管理」から「構成」を開き、検索窓に enable logging と入力する
3. Server > SQL Engine > Logging > Query Statistics Logging > Enable Logging の値を INFO に変更する
4. 「適用」→「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行目に出力される主なカラム名の名称と内容については以下の通りです。

typeについて

typeに入る QUERY / SCAN / PROCEDUREについてはそれぞれ以下を意味します。

• QUERY: TDVサーバで発行されたクエリ
• SCAN: データソース内で実際に処理されたクエリ
• PROCEDURE: プロシージャ（SQLスクリプト、パラメータ化クエリ）

バックグラウンドタスクについて

通常、SQLスクリプトを実行する際には、バックグラウンドタスクが使用されることがあります。
これは、プロシージャの主ステートメントを実行中に、これとは別に別のタスクが実行される場合に発生します。
システム・タスクであったり、他のプロシージャやAPIを実行するための呼び出しであったりと、様々です。

クエリ統計情報ログのローテーションポリシーについて

クエリ統計情報ログのローテーションポリシーを変更する場合はServer > SQL Engine > Logging > Query Statistics Loggingにある各種パラメータを変更します。