SPARQLthon89/VirtuosoQueryLog

提供：TogoWiki

VirtuosoのSPARQLクエリログ

山本さんからSPARQLのクエリログが残っていないかと質問があったので調べた。
また、RDFポータルにデータを増やすためにクエリ応答を調査されているとのことで関連するので記載する。

ログ出力設定

公式ドキュメント: Query Logging

デフォルト設定では残らないので、virtuoso.iniに"QueryLog"追加して再起動する。

[Parameters] //パラメータセグメントに追記する
QueryLog = /path/to/install/directory/var/lib/virtuoso/db/virtuoso.qrl

設定が済んで、クエリをかけると指定ファイルが出力さる
ただしこの中身はバイナルファイルでそのまま読めず、isqlからSQLでログデータを検索する。

SPARQLログ

設定するとSYS_QUERY_LOGテーブルに対してSQLが叩けるようになる。設定してないとエラー。
SQLや内部のスケジュール的実行も残るようなので、エンドポイントからのクエリ実行ユーザ(デフォルトなら'SPARQL')で絞り込む。
例えば、2020/2/25に実行したエンドポイントからのクエリログ一覧は以下のように取得する。

SQL> SELECT ql_id, ql_start_dt, ql_text FROM SYS_QUERY_LOG WHERE ql_start_dt >= cast('2020-02-25' as datetime) AND ql_start_dt < cast('2020-02-26' as datetime) AND ql_user = 'SPARQL';
ql_id            ql_start_dt      ql_text
INTEGER          TIMESTAMP        LONG VARCHAR
_______________________________________________________________________________

389              2020.2.25 20:25.7 545429000  isnull (sparql_to_sql_text ('{ define sql:big-data-const 0 ' || ? || '\n}'))
390              2020.2.25 20:25.14 550879000  sparql {
#output-format:text/html
define sql:signal-void-variables 1 SELECT ?s
{
 ?s ?p ?o
} LIMIT 20
}
// 389と390の2件が取得できた。実行時間とクエリ文から調べるql_idを特定

isql経由でSPARQLを指定した場合は接続ユーザ'dba'などになる。

なお、ql_idが一意キーかと思いきや、ql_id + ql_start_dt で主キーらしい(Virtuosoの再起動ごとにid counterが戻ってしまうのかも...)。
ということでql_idと日付(2020-02-25)を指定して特定のクエリの状況をだす

SQL> SELECT * FROM SYS_QUERY_LOG WHERE  ql_start_dt >= cast('2020-02-25' as datetime) AND ql_start_dt < cast('2020-02-26' as datetime) AND ql_id = 390;
(省略)

リクエストがあったクエリ文はql_textカラムで確認できる。改行されてて見辛い...

SQL> SELECT ql_id, ql_error FROM SYS_QUERY_LOG WHERE ql_start_dt >= cast('2020-02-25' as datetime) AND ql_start_dt < cast('2020-02-26' as datetime) AND ql_user = 'SPARQL';
---
ql_id            ql_text
INTEGER          LONG VARCHAR
_______________________________________________________________________________

390              sparql {
#output-format:text/html
define sql:signal-void-variables 1 SELECT ?s
{
 ?s ?p ?o
} LIMIT 20
}
---

文法エラー等のエラーメッセージはql_errorカラムで確認できる

SQL> SELECT ql_id, ql_error FROM SYS_QUERY_LOG WHERE ql_start_dt >= cast('2020-02-25' as datetime) AND ql_start_dt < cast('2020-02-26' as datetime) AND ql_user = 'SPARQL';
ql_id            ql_error
INTEGER          VARCHAR
_______________________________________________________________________________

390              NULL #成功時はNULL
436              SP030: SPARQL compiler, line 6: syntax error at 'LIMIT20' before '}'

しかしエラー時にユーザが送ったSPARQLは見れない（謎）

SQL> SELECT ql_id, ql_text  FROM SYS_QUERY_LOG WHERE ql_start_dt >= cast('2020-02-25' as datetime) AND ql_start_dt < cast('2020-02-26' as datetime) AND ql_user = 'SPARQL' AND ql_id = 436;
ql_id            ql_text
INTEGER          LONG VARCHAR
_______________________________________________________________________________

436              isnull (sparql_to_sql_text ('{ define sql:big-data-const 0 ' || ? || '\n}'))

SPARQLクエリパフォーマンス調査

SYS_QUERY_LOGには色々な項目があり、それぞれの意味はドキュメントに記載されている。
パフォーマンスの診断時に使うようなクエリ実行計画文(ql_plan)の他、ディスクのwait時間を出してくれそうなql_c_disk_wait等あり、詳細調べていないが、クエリのボトルネックがわかりそうな項目がある。

テーブルのカラム一覧を表示するコマンド
SQL> columns SYS_QUERY_LOG;