Prestoのslow queryの可視化

MySQLのslow queryを可視化するnata2というプロダクトがあります。詳細は下記参照。

MySQL Casual Talks vol 6.でNata2について発表してきた - Studio3104::BLOG.new

で、別にこれMySQLじゃなくてもいけんじゃねって思ったのでPrestoに適用してみました。

Prestoだとクエリの実行履歴はsys.queryテーブルに入ります。
こいつのスキーマはこんな感じ。end - createdがクエリ実行時間になります。MySQLとちがって単位はミリ秒です。これをnata2にpostします。

nata2は他にもいくつかpostしないといけないのですが、lock_time, rows_sent, rows_examinedはMySQL特有の値なのでそこは0で埋めました。

ここまでは良いのですが、問題になってくるのはどのクエリまで処理したかという部分をどうハンドリングするかなのですが、今回そこは厳密にやってないです。

下記のような感じでpyhiveを使ってPrestoにつないでrequestsを使ってnata2にpostします。引数が1つ必要でquery_idを渡します。これがどこまでのquery_idをすでに処理したかを示します。
今回は5秒より時間がかかったらslow queryと判断しています。

import sys
from pyhive import presto
import requests

argvs = sys.argv
argc = len(argvs)
if argc != 2:
    sys.exit(1)
max_query_id = argvs[1]

nata_url="..."
service_name="..."
host_name="..."
database_name="..."

cursor = presto.connect(host='...').cursor()
cursor.execute("SELECT * FROM sys.query WHERE state = 'FINISHED' and query_id > '%s' ORDER BY query_id DESC LIMIT 100" % (max_query_id))

for i, row in enumerate(cursor.fetchall()):
    if i == 0:
        max_query_id = row[1]
    state = row[2]
    query_id = row[1]
    user = row[3]
    query = row[4]
    created = int(row[8])
    end = int(row[11])
    elapsed = end - created
    if elapsed > 5000:
        data = {}
        data["datetime"] = created/1000
        data["user"] = user
        data["host"] = "..."
        data["query_time"] = float(elapsed)/1000
        data["lock_time"] = 0
        data["rows_sent"] = 0
        data["rows_examined"] = 0
        data["sql"] = query
        r = requests.post(nata_url + "/api/1/" + service_name + "/" + host_name + "/" + database_name, data)
        if r.status_code != 200:
            print "error occurs!"
            print r

print max_query_id

上記pythonスクリプトをキックするのが下記シェルスクリプトです。どのquery_idまで処理したかをファイルに保存します。

#!/bin/sh

data_path=".../presto_slow_query.dat"

max_query_id=`cat $data_path`

next_max_query_id=`python presto_slow_query.py $max_query_id`

echo $next_max_query_id > $data_path

このシェルスクリプトをcronで実行するのですが、実行タイミングで state = 'RUNNING' なクエリがあってそのクエリの実行時間が5秒を超えた場合はnata2にpostされません。
厳密ではないと言ったのはこの部分です。まあそれ以外にも頻繁にクエリ実行された場合はひろえない部分も出てくると思います。

そんなわけで参考程度にしかならないのですが可視化するとこんな感じになります。