要約
- Redashのクエリ実行にはタイムアウトを設定できる
- 手動実行 : REDASH_ADHOC_QUERY_TIME_LIMIT (v3.0.0~)
- 定期実行 : REDASH_SCHEDULED_QUERY_TIME_LIMIT (v8.0.0~)
- 本家ドキュメント側の記載が漏れていたのでprを出した
環境
- macOS 10.15.5
- docker desktop community 2.4.0.0 (48506)
- Redash 8.0.0
手順
github.com
例によって、カック先生(id:kakku22)のredash-hands-onを利用する。
ただ、今回はクエリのタイムアウトについて検証を行いたいため下記について編集する。
docker-compose.ymlを参照すると分かるがRedash向けの環境変数がenvファイルにまとめられている。
今回追加する設定値はすべてRedashに関係する環境変数なのでここに追加すればOK。
追加するのは下記の3行
REDASH_ADDITIONAL_QUERY_RUNNERS=redash.query_runner.python
REDASH_ADHOC_QUERY_TIME_LIMIT=5
REDASH_SCHEDULED_QUERY_TIME_LIMIT=10
1行目でデータソースにPythonを追加し
2行目,3行目でそれぞれ手動実行, 定期実行クエリのタイムアウトを設定している。
起動時の設定
README.mdにはdocker-compose up -dと記載されているが
今回は実行時に各コンテナが出力するログを確認したいのでdocker-compose upと実行する。
データソースの追加
初回ログインまでチュートリアルにそって確認後はデータソースにPythonを追加する。
Modules to import prior to running the scriptには、datetime, timeを追加する必要がある。
(前に書いた記事で少し触れたが、RedashのPythonには何かと制限が多い)
実行するクエリは以下
import time
from datetime import datetime, timedelta
td_jst = timedelta(hours=9)
sleep = 4
print("start")
time.sleep(sleep)
result = {}
add_result_column(result, 'finished_at', '', 'string')
add_result_row(
result,
{'finished_at' : (datetime.now() + td_jst).strftime('%Y-%m-%d %H:%M:%S')}
)
print("finish")
実行すると下記のような結果が得られた
クエリの実行時間からもsleepが効いていることが確認できる。
ADHOC_QUERY
まずは手動実行クエリのタイムアウト動作を確認する。
手動実行クエリのタイムアウトは5秒なのでsleepを6秒に設定して実行する。
実行後ブラウザには下記のようなエラーが表示されクエリが中断されたことが分かる。
同じタイミングのdocker-compose側のログは下記。
adhoc_worker_1で例外が発生していることがわかる。
...
adhoc_worker_1 | [2020-10-23 02:59:45,953][PID:1][WARNING][MainProcess] Soft time limit (5s) exceeded for redash.tasks.execute_query[6a76c71c-5a52-4605-b27a-ae5d570e617b]
adhoc_worker_1 | [2020-10-23 02:59:45,954][PID:24][INFO][ForkPoolWorker-3] task_name=redash.tasks.execute_query task_id=6a76c71c-5a52-4605-b27a-ae5d570e617b task=execute_query query_hash=60a9cad8d5384755b62d1971f9d914f0 data_length=None error=[<class 'billiard.exceptions.SoftTimeLimitExceeded'> SoftTimeLimitExceeded()]
adhoc_worker_1 | [2020-10-23 02:59:45,957][PID:24][ERROR][ForkPoolWorker-3] Task redash.tasks.execute_query[6a76c71c-5a52-4605-b27a-ae5d570e617b] raised unexpected: QueryExecutionError("<class 'billiard.exceptions.SoftTimeLimitExceeded'> SoftTimeLimitExceeded()",)
adhoc_worker_1 | Traceback (most recent call last):
adhoc_worker_1 | File "/usr/local/lib/python2.7/site-packages/celery/app/trace.py", line 385, in trace_task
adhoc_worker_1 | R = retval = fun(*args, **kwargs)
adhoc_worker_1 | File "/app/redash/worker.py", line 84, in __call__
adhoc_worker_1 | return TaskBase.__call__(self, *args, **kwargs)
adhoc_worker_1 | File "/usr/local/lib/python2.7/site-packages/celery/app/trace.py", line 648, in __protected_call__
adhoc_worker_1 | return self.run(*args, **kwargs)
adhoc_worker_1 | File "/app/redash/tasks/queries.py", line 436, in execute_query
adhoc_worker_1 | scheduled_query).run()
adhoc_worker_1 | File "/app/redash/tasks/queries.py", line 382, in run
adhoc_worker_1 | raise result
adhoc_worker_1 | QueryExecutionError: <class 'billiard.exceptions.SoftTimeLimitExceeded'> SoftTimeLimitExceeded()
...
SCHEDULED_QUERY
次には定期実行クエリの動作を確認する。
画面左下のRefresh Scheduleから定期実行の頻度を設定できる。
まずは設定時間が6秒のまま定期実行クエリのインターバルを毎分に設定して動作することを確認する。
...
server_1 | [2020-10-23 02:59:46,163][PID:13][INFO][metrics] method=GET path=/api/jobs/6a76c71c-5a52-4605-b27a-ae5d570e617b endpoint=job status=200 content_type=application/json content_length=198 duration=1.07 query_count=2 query_duration=2.51
nginx_1 | 172.23.0.1 - - [23/Oct/2020:02:59:46 +0000] "GET /api/jobs/6a76c71c-5a52-4605-b27a-ae5d570e617b HTTP/1.1" 200 183 "http://localhost/queries/1/source" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36" "-"
scheduler_1 | [2020-10-23 03:00:00,308][PID:22][INFO][Beat] Scheduler: Sending due task refresh_queries (redash.tasks.refresh_queries)
scheduler_1 | [2020-10-23 03:00:00,310][PID:1][INFO][MainProcess] Received task: redash.tasks.refresh_queries[543a01a0-ec5e-4708-b191-1f171619d3e5]
scheduler_1 | [2020-10-23 03:00:00,311][PID:33][INFO][ForkPoolWorker-12] task_name=redash.tasks.refresh_queries task_id=543a01a0-ec5e-4708-b191-1f171619d3e5 Refreshing queries...
scheduler_1 | [2020-10-23 03:00:00,315][PID:33][INFO][ForkPoolWorker-12] task_name=redash.tasks.refresh_queries task_id=543a01a0-ec5e-4708-b191-1f171619d3e5 Done refreshing queries. Found 0 outdated queries: []
scheduler_1 | [2020-10-23 03:00:00,317][PID:33][INFO][ForkPoolWorker-12] Task redash.tasks.refresh_queries[543a01a0-ec5e-4708-b191-1f171619d3e5] succeeded in 0.0063627999989s: None
scheduler_1 | [2020-10-23 03:00:30,305][PID:22][INFO][Beat] Scheduler: Sending due task sync_user_details (redash.tasks.sync_user_details)
scheduler_1 | [2020-10-23 03:00:30,307][PID:1][INFO][MainProcess] Received task: redash.tasks.sync_user_details[e830e682-bb32-4266-b87f-bd84183f1a2c] expires:[2020-10-23 03:01:15.305506+00:00]
scheduler_1 | [2020-10-23 03:00:30,308][PID:22][INFO][Beat] Scheduler: Sending due task refresh_queries (redash.tasks.refresh_queries)
scheduler_1 | [2020-10-23 03:00:30,317][PID:33][INFO][ForkPoolWorker-12] Task redash.tasks.sync_user_details[e830e682-bb32-4266-b87f-bd84183f1a2c] succeeded in 0.00900940000065s: None
scheduler_1 | [2020-10-23 03:00:30,319][PID:1][INFO][MainProcess] Received task: redash.tasks.refresh_queries[81cb8e71-918d-4fa5-8950-03fe44bcfc31]
scheduler_1 | [2020-10-23 03:00:30,320][PID:33][INFO][ForkPoolWorker-12] task_name=redash.tasks.refresh_queries task_id=81cb8e71-918d-4fa5-8950-03fe44bcfc31 Refreshing queries...
scheduler_1 | [2020-10-23 03:00:30,330][PID:33][INFO][ForkPoolWorker-12] Inserting job for 60a9cad8d5384755b62d1971f9d914f0 with metadata={'Username': 'Scheduled', 'Query ID': 1}
scheduler_1 | [2020-10-23 03:00:30,347][PID:33][INFO][ForkPoolWorker-12] [60a9cad8d5384755b62d1971f9d914f0] Created new job: 255c632f-b198-4018-883c-bc295996bb7b
scheduled_worker_1 | [2020-10-23 03:00:30,347][PID:1][INFO][MainProcess] Received task: redash.tasks.execute_query[255c632f-b198-4018-883c-bc295996bb7b]
scheduler_1 | [2020-10-23 03:00:30,348][PID:33][INFO][ForkPoolWorker-12] task_name=redash.tasks.refresh_queries task_id=81cb8e71-918d-4fa5-8950-03fe44bcfc31 Done refreshing queries. Found 1 outdated queries: [1]
scheduled_worker_1 | [2020-10-23 03:00:30,352][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=255c632f-b198-4018-883c-bc295996bb7b task=execute_query state=load_ds ds_id=1
scheduler_1 | [2020-10-23 03:00:30,353][PID:33][INFO][ForkPoolWorker-12] Task redash.tasks.refresh_queries[81cb8e71-918d-4fa5-8950-03fe44bcfc31] succeeded in 0.0330446000007s: None
scheduled_worker_1 | [2020-10-23 03:00:30,356][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=255c632f-b198-4018-883c-bc295996bb7b task=execute_query state=executing_query query_hash=60a9cad8d5384755b62d1971f9d914f0 type=python ds_id=1 task_id=255c632f-b198-4018-883c-bc295996bb7b queue=scheduled_queries query_id=1 username=Scheduled
scheduled_worker_1 | [2020-10-23 03:00:36,366][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=255c632f-b198-4018-883c-bc295996bb7b task=execute_query query_hash=60a9cad8d5384755b62d1971f9d914f0 data_length=213 error=[None]
scheduled_worker_1 | [2020-10-23 03:00:36,368][PID:22][INFO][ForkPoolWorker-1] Inserted query (60a9cad8d5384755b62d1971f9d914f0) data; id=None
scheduled_worker_1 | [2020-10-23 03:00:36,378][PID:22][INFO][ForkPoolWorker-1] Updated 1 queries with result (60a9cad8d5384755b62d1971f9d914f0).
scheduled_worker_1 | [2020-10-23 03:00:36,380][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=255c632f-b198-4018-883c-bc295996bb7b task=execute_query state=checking_alerts query_hash=60a9cad8d5384755b62d1971f9d914f0 type=python ds_id=1 task_id=255c632f-b198-4018-883c-bc295996bb7b queue=scheduled_queries query_id=1 username=Scheduled
scheduled_worker_1 | [2020-10-23 03:00:36,382][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=255c632f-b198-4018-883c-bc295996bb7b task=execute_query state=finished query_hash=60a9cad8d5384755b62d1971f9d914f0 type=python ds_id=1 task_id=255c632f-b198-4018-883c-bc295996bb7b queue=scheduled_queries query_id=1 username=Scheduled
scheduler_1 | [2020-10-23 03:00:36,382][PID:1][INFO][MainProcess] Received task: redash.tasks.check_alerts_for_query[e25e7ceb-4d64-4cc6-9925-93d476cc9b97]
scheduled_worker_1 | [2020-10-23 03:00:36,383][PID:22][INFO][ForkPoolWorker-1] Task redash.tasks.execute_query[255c632f-b198-4018-883c-bc295996bb7b] succeeded in 6.0339485s: 230
...
最後の行の succeeded in 6.0339485s から分かる通り問題なく動作しているようだ。
次にタイムアウトの10秒を超えるようにsleepを15秒に設定して待機する。
手動実行ではないためブラウザ上にはエラーは表示されないものの
docker-compose側では下記のようなエラーが表示されているためタイムアウトが動作していることがわかる。
...
scheduled_worker_1 | [2020-10-23 03:05:30,343][PID:1][INFO][MainProcess] Received task: redash.tasks.execute_query[a266bd40-5abe-4515-ad69-f2f756142b7b]
scheduler_1 | [2020-10-23 03:05:30,346][PID:35][INFO][ForkPoolWorker-14] Task redash.tasks.refresh_queries[a9cd4248-7f95-434f-9b76-d4de42ab34b1] succeeded in 0.0338508000023s: None
scheduled_worker_1 | [2020-10-23 03:05:30,349][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=a266bd40-5abe-4515-ad69-f2f756142b7b task=execute_query state=load_ds ds_id=1
scheduled_worker_1 | [2020-10-23 03:05:30,354][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=a266bd40-5abe-4515-ad69-f2f756142b7b task=execute_query state=executing_query query_hash=115c0c43431f5ba5c1284589e62738a4 type=python ds_id=1 task_id=a266bd40-5abe-4515-ad69-f2f756142b7b queue=scheduled_queries query_id=1 username=Scheduled
scheduled_worker_1 | [2020-10-23 03:05:40,347][PID:1][WARNING][MainProcess] Soft time limit (10s) exceeded for redash.tasks.execute_query[a266bd40-5abe-4515-ad69-f2f756142b7b]
scheduled_worker_1 | [2020-10-23 03:05:40,348][PID:22][INFO][ForkPoolWorker-1] task_name=redash.tasks.execute_query task_id=a266bd40-5abe-4515-ad69-f2f756142b7b task=execute_query query_hash=115c0c43431f5ba5c1284589e62738a4 data_length=None error=[<class 'billiard.exceptions.SoftTimeLimitExceeded'> SoftTimeLimitExceeded()]
scheduled_worker_1 | [2020-10-23 03:05:40,357][PID:22][ERROR][ForkPoolWorker-1] Task redash.tasks.execute_query[a266bd40-5abe-4515-ad69-f2f756142b7b] raised unexpected: QueryExecutionError("<class 'billiard.exceptions.SoftTimeLimitExceeded'> SoftTimeLimitExceeded()",)
scheduled_worker_1 | Traceback (most recent call last):
scheduled_worker_1 | File "/usr/local/lib/python2.7/site-packages/celery/app/trace.py", line 385, in trace_task
scheduled_worker_1 | R = retval = fun(*args, **kwargs)
scheduled_worker_1 | File "/app/redash/worker.py", line 84, in __call__
scheduled_worker_1 | return TaskBase.__call__(self, *args, **kwargs)
scheduled_worker_1 | File "/usr/local/lib/python2.7/site-packages/celery/app/trace.py", line 648, in __protected_call__
scheduled_worker_1 | return self.run(*args, **kwargs)
scheduled_worker_1 | File "/app/redash/tasks/queries.py", line 436, in execute_query
scheduled_worker_1 | scheduled_query).run()
scheduled_worker_1 | File "/app/redash/tasks/queries.py", line 382, in run
scheduled_worker_1 | raise result
scheduled_worker_1 | QueryExecutionError: <class 'billiard.exceptions.SoftTimeLimitExceeded'> SoftTimeLimitExceeded()
...
タイムアウトが設定出来るのでうまく設定してやれば定期実行クエリがキューに詰まることは無くすことができそう。
その一方で、定期実行クエリが失敗した場合に結果は更新されず一見しただけでは失敗したかどうか分からない。
QueriesからLast Executed Atを参照する、ないしは結果内に最後に実行した時間を含めるようにしないと
古いデータと気づかずに利用してしまう可能性があるのでそこは注意が必要。
雑記
手動実行クエリについて調査していた時に__init__.pyを眺めていて
ドキュメント化されてないけど定期実行にもタイムアウトあるやんけと思い
みたいなことを投稿したのだけど
おそらく追記漏れだろう、ということで本家ドキュメントにもprを出した。
マージされるといいですね。おわり。
