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

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

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

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

## 1. mysql -vvv オプション
[リファレンス](https://dev.mysql.com/doc/refman/5.6/ja/batch-mode.html)
最初はこの方法で取得しようと思っていました。
`mysql`コマンドに`-vvv`をつけることで実行時間を取得できます。

```shell:test.sh
mysql -vvv -u root -e "INSERT INTO demo.demo VALUES(1);"
```

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

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

Query OK, 1 row affected (0.02 sec)

Bye
```

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

```shell: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`で開き括弧`(`と念の為に閉じ括弧`)`で区切り、その後空白で区切って表示しています。
とりあえず実行してみます。

```bash
$ sh test.sh
0.02
```

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

```bash
Query OK, 1 row affected (0.02 sec)
```

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

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

```bash
$ 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 プロファイリング
[リファレンス](https://dev.mysql.com/doc/refman/5.6/ja/show-profile.html)

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

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

## 3. timeコマンド
[リファレンス](https://linuxjm.osdn.jp/html/LDP_man-pages/man1/time.1.html)

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

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

```bash
$ time sleep 1

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

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

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

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

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

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

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

結果が変わらない ..
[調べて](http://numa08.blogspot.com/2012/01/time.html)みるとtimeコマンドは以下の仕様なのだそうです。
> 1行全て実行した後に時間が出力される

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

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

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

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

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

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

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

# さいごに
```bash
$ (time -p mysql -u root -e "SELECT * FROM demo.demo;") |& head -1 | awk '{print $2}'
```

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

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

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

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

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

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

[^2]: `|&`が`2>&1`の省略形のようなのでこちらを使っています。