More than 5 years have passed since last update.

【ShellScript】mysqlコマンドの実行時間を取得する。

Last updated at 2019-05-08Posted at 2019-03-14

はじめに

はじめてのShellScript
だいぶ詰まったのでメモとして投稿します。
ツッコミ募集してます。

mysqlコマンドを使って重たいクエリのクエリ実行時間を取得したい。
AWSのクラウドウォッチメトリクスに値をなげたいので0.00のフォーマットで取得したい。

ざっと調べたところ以下の3種類で実行時間が取得できるようでした。

リファレンス
最初はこの方法で取得しようと思っていました。
mysqlコマンドに-vvvをつけることで実行時間を取得できます。

test.sh

mysql -vvv -u root -e "INSERT INTO demo.demo VALUES(1);"

上記のシェルを用意します。
実行したら以下のような結果が取得できます。

$ sh test.sh
--------------
INSERT INTO demo.demo VALUES(1)
--------------

Query OK, 1 row affected (0.02 sec)

Bye

(0.02 sec)を取れればできそうかな ..?
ということで要件を満たすためにコマンドを以下のように加工しました。

test.sh

mysql -vvv -u root -e "INSERT INTO demo.demo VALUES(1);" | tail -3 | awk -F'(' '{print $2}' | awk -F')' '{print $1}' | awk '{print $1}'

力技です。
tailで最下3行を取得してawkで開き括弧(と念の為に閉じ括弧)で区切り、その後空白で区切って表示しています。
とりあえず実行してみます。

$ sh test.sh
0.02

よし、できた！というところで嫌なことに気が付きました。
mysqlコマンドの実行結果を思い出します。

Query OK, 1 row affected (0.02 sec)

0.02 sec ..?
あれ、これminになる ..?

取得に1分以上を要するSELECT文を実行してみます。

$ mysql -vvv -u root -e "おもたいせれくとぶん;" | tail -3
403802 rows in set (10 min 39.23 sec)

Bye

はい。min が追加されましたね。
これhourとかもあるんでしょうか ..。
流石に1時間かかるqueryはないと思いますが、min * 60 の処理をいれないといけないので別の方法で取得することにします。

注記
これらのステートメントは、MySQL 5.6.7 の時点では非推奨であり、将来の MySQL リリースで削除される予定です。代わりに、パフォーマンススキーマを使用してください。第22章「MySQL パフォーマンススキーマ」を参照してください。

時間の都合上諦めました。

書式
time [options] command [arguments...]

timeコマンドはcommandに設定したコマンドの実行時間を取得できるようです。
厳密なクエリの実行時間にはならないですが、良しとします。
timeコマンドを実行した結果は以下となります。

$ time sleep 1

real    0m1.002s
user    0m0.001s
sys     0m0.000s

更に-pオプションを使用すると 0m0.000sの形式から以下の形式に変更してくれます。

$ time -p sleep 1
real 1.00
user 0.00
sys 0.00

早速mysqlコマンドを実行してみます。

$ time -p mysql -u root -e "SELECT * FROM demo.demo;"
real 0.10
user 0.00
sys 0.00

取得できたのでパイプでゴリ押しましょう！

$ time -p mysql -u root -e "SELECT * FROM demo.demo;" | head -1 | awk '{print $2}'
real 0.10
user 0.00
sys 0.00

結果が変わらない ..
調べてみるとtimeコマンドは以下の仕様なのだそうです。

1行全て実行した後に時間が出力される

(time ls -la ) 2>&1 | grep sys
とするのが正解。

この時点では標準出力と標準エラー出力を理解していなかったので理解するのに時間がかかりました。

自分の言葉に直してみると括弧（``）をつけてコマンドを実行するとコマンドが別プロセスで実行され、以下の条件を満たします。

1行全て実行した後に時間が出力される

その後に2>&1をつけることで標準エラー出力と標準出力を一括でリダイレクトをしているようです。

上記を踏まえて以下のコマンドが出来上がりました¹。

$ (time -p mysql -u root -e "SELECT * FROM demo.demo;") |& head -1 | awk '{print $2}'
0.10

はい、期待通りの値が帰ってきました。

$ (time -p mysql -u root -e "SELECT * FROM demo.demo;") |& head -1 | awk '{print $2}'

この記事はこのコマンドで終わらせましたが欠陥が存在します。
mysqlコマンドの出力結果に標準エラー出力があると出力結果に差異が出てしまいます。

以下が例です。mysqlコマンドにパスワードをベタ打ちするとwarningが出力されるのでUsingが取得されてしまいます。

$ (time -p mysql -u root -proot -e "SELECT * FROM demo.demo;") |& head -1 | awk '{print $2}'
Using

##3月29追記
結局以下のようにコマンドを変更しました ..

$ (time -p mysql -u root -e "SELECT * FROM demo.demo;") |& grep real | awk'{print $2}'

~~mysql -vvvでゴリ押しがやっぱり無難だった？~~