Qiita Teams that are logged in
You are not logged in to any team

Log in to Qiita Team
Community
OrganizationEventAdvent CalendarQiitadon (β)
Service
Qiita JobsQiita ZineQiita Blog
1
Help us understand the problem. What are the problem?

More than 1 year has passed since last update.

posted at

updated at

Organization

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

はじめに

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

やりたいこと

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

やりかた

ざっと調べたところ以下の3種類で実行時間が取得できるようでした。
1. mysql -vvv オプション
2. mysql プロファイリング
3. timeコマンド

1. mysql -vvv オプション

リファレンス
最初はこの方法で取得しようと思っていました。
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 の処理をいれないといけないので別の方法で取得することにします。

2. mysql プロファイリング

リファレンス

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

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

3. timeコマンド

リファレンス

書式
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をつけることで標準エラー出力と標準出力を一括でリダイレクトをしているようです。

上記を踏まえて以下のコマンドが出来上がりました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でゴリ押しがやっぱり無難だった?


  1. |&2>&1の省略形のようなのでこちらを使っています。 

Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
1
Help us understand the problem. What are the problem?