shスクリプトから使うストップウォッチ

#**はじめに**
shスクリプトから使うストップウォッチを作りました。
/proc/uptimeを使用するバージョンと
date(GNU)を使用するバージョの２種類あります。
両方ともcentos7で動作確認しています。

#**機能概要**
| shスクリプト | 機能|備考|
|:--|:--|:--|
|スクリプト共通   |・watch_start呼び出しとwatch_stop呼び出しの間に実行された処理の経過時間を計測します。<BR/>watch_elapsed_timeを呼び出すと、経過時間が表示されます(標準出力)。|   |
| stop_watch_proc_uptime.sh |計測時間の単位は0.01秒です。|/proc/uptimeを使用しています。   |
| stop_watch_date.sh  |計測時間の単位はナノ秒です。 |date(GNU)コマンドを使用しています。   |

#**shスクリプトと使用方法**

#####**【shスクリプト】**
/proc/uptime版

~~~bash:stop_watch_proc_uptime.sh
#!/bin/bash
watch_start(){
	local watch_id=$1
	local now
	read  now dummy < /proc/uptime
	eval export __START_TIME_${watch_id}=${now}
}
watch_stop(){
	local watch_id=$1
	local now dummy
	read  now dummy < /proc/uptime
	eval export __END_TIME_${watch_id}=${now}
}
watch_elapsed_time(){
	local watch_id=$1
	local start end time ae
	eval start=\${__START_TIME_${watch_id}}
	eval end=\${__END_TIME_${watch_id}}
	ae="${end} - ${start}"
	time=`bc -l <<<${ae}`
	printf "%f\n" ${time}
}
export -f watch_start
export -f watch_stop
export -f watch_elapsed_time

~~~
---
GNU　date版

~~~bash:stop_watch_date.sh
#!/bin/bash
watch_start(){
	local watch_id=$1
	local now
	now=$(date "+%s.%N")
	eval export __START_TIME_${watch_id}=${now}
}
watch_stop(){
	local watch_id=$1
	local now dummy
	now=$(date "+%s.%N")
	eval export __END_TIME_${watch_id}=${now}
}
watch_elapsed_time(){
	local watch_id=$1
	local start end time
	eval start=\${__START_TIME_${watch_id}}
	eval end=\${__END_TIME_${watch_id}}
	ae="${end} - ${start}"
	time=`bc -l <<<${ae}`
	printf "%f\n" ${time}
}
export -f watch_start
export -f watch_stop
export -f watch_elapsed_time

~~~

#####**【使用方法】**

~~~bash:
#sourceまたは.でshスクリプトを読み込み
source stop_watch_proc_uptime     #date版を使用する場合はstop_watch_date.shを読み込む。
                                  #PATHが通っていないところに配置した場合はパス名で読み込む。

#計測開始
watch_start ID #IDはwatchを識別する記号です。省略可能です。
               #IDには英字、アンダースコア(_)で始まる英数字、アンダースコアが使用できます。
               #英大文字と英小文字は区別されます。


#計測対象の処理

#計測終了
watch_stop ID

#計測結果
watch_elapsed_time ID    #計測結果(秒)が表示されます(標準出力)。
~~~

#**使用例**

このツールの使用例です。性能測定を兼ねて作りました。
関数f1_A1では`:`を、
関数f1_A2では`:`と`watch_start`と`watch_stop`を100,000回実行し、結果の差を実行回数で割った値を表示するものです。



watch_start/watch_stop

~~~bash:qprfm.sh

#!/bin/bash
export NUM=100000 #100,000
export DEBUG=

f1_A1(){
	:
}
f1_A2(){
	:
	watch_start DUMMY
	watch_stop DUMMY
}
f1(){
	local lib=$1
	local i
	local elapsed_time_A1
	local elapsed_time_A2
	source ${lib}

	watch_start A1
	for((i=0; i<NUM;i++))
	do
		f1_A1
	done
	watch_stop A1

	watch_start A2
	for((i=0; i<NUM;i++))
	do
		f1_A2
	done
	watch_stop A2
	elapsed_time_A1=$(watch_elapsed_time A1)
	elapsed_time_A2=$(watch_elapsed_time A2)
	gawk 'BEGIN{printf("%f %f %f\n", ('${elapsed_time_A2}'-'${elapsed_time_A1}')*1000/'${NUM}', '${elapsed_time_A1}', '${elapsed_time_A2}');}' /dev/null
}
mainp(){
	local lib=$1
	local n=0
	local sum=0
	for i in 1 2 3
	do
		read t elapsed_time_A1 elapsed_time_A2 <<< $(f1 ${lib} ${NUM})
		sum=$(gawk 'BEGIN{sum='${sum}' + '${t}';printf("%f\n", sum);}' /dev/null)
		n=$(expr ${n} + 1)
		if [ "${DEBUG}" != "" ]
		then
			printf "\t\t\t\t\telapsed_time_A1=%f\n" "${elapsed_time_A1}"
			printf "\t\t\t\t\telapsed_time_A2=%f\n" "${elapsed_time_A2}"
			printf "\t\t\t\t\tt=%f\n" "${t}"
		fi
	done
	ave=$(gawk 'BEGIN{ave='${sum}' / '${n}';printf("%f\n", ave);}' /dev/null)
	printf "file=%s\n" "$0"
	printf "lib=%s\n" "${lib}"
	printf "NUM=%d\n" ${NUM}
	printf "elapsed_time(ms)=\t%f\n" ${ave}
}
echo "============================================"
mainp ./stop_watch_proc_uptime.sh
echo "============================================"
mainp ./stop_watch_date.sh

~~~
~~~bash:実行結果
============================================
file=qprfm_1.sh
lib=./stop_watch_proc_uptime.sh
NUM=100000
elapsed_time(ms)=	0.117633
============================================
file=qprfm_1.sh
lib=./stop_watch_date.sh
NUM=100000
elapsed_time(ms)=	2.352937

~~~

#**処理性能**

処理性能(1計測あたりの処理時間)は以下のとおりです。

|shスクリプト|watch_start/watch_stopの処理時間|
|:--|:--|
|stop_watch_proc_uptime.sh|0.12ms / 1計測   |
|stop_watch_date.sh|2.35ms / 1計測   |


計測したときのスクリプトは省略しますが、watch_elapsed_timeの処理時間は以下です。

|shスクリプト|watch_elapsed_timeの処理時間|
|:--|:--|
|stop_watch_proc_uptime.sh|0.00ms / 1計測   |
|stop_watch_date.sh|0.00ms / 1計測   |

こちらも計測したときのスクリプトは省略しますが、watch_start、watch_stop、watch_elapsed_time
を１回ずつ100,000回実行したときの基本統計量です。

【stop_watch_proc_uptime.shで計測したときの基本統計量】
n=100000
min=0
max=0.01
med=0
ave=7.18E-05　　　※0.0000718秒、0.0718ms
sum=7.18
svar=7.12845E-07
uvar=7.12852E-07
ssd=0.000844301
usd=0.000844306　 ※不偏標準偏差
skew=11.6742
kurt=134.29

先の性能測定結果(stop_watch_proc_uptime.shのwatch_startとwatch_stopを実行した結果)は0.12msですので、今回の計測は半分の0.06msになるはずなのですが、結果は0.0718msでした。統計的な評価は(能力的に)できませんが、誤差の範囲のような気がします。

【stop_watch_date.shで計測したときの基本統計量】
n=100000
min=0.000837
max=0.040842
med=0.000907
ave=0.000948176　　　※0.948176ms
sum=94.8176
svar=9.71973E-08
uvar=9.71982E-08
ssd=0.000311765
usd=0.000311766
skew=44.3541
kurt=3574.56

先の性能測定結果(stop_watch_date.shのwatch_startとwatch_stopを実行した結果)は2.35msですので、今回の計測は半分の1.175msになるはずなのですが、結果は0.948176msでした。

基本統計量は、以下で紹介したツールで計算しました。こちらも参照してみてください。

[gawkで基本統計量を計算する](https://qiita.com/EjiriAkira/items/e92e919bb9ee1c52b7ae)



#**環境**

ホスト　Windows10 COREi7 
VM　　　VirtualBox バージョン 5.2.6 r120293 (Qt5.6.2)
　　　　　CentOS Linux release 7.4.1708 (Core)
GNU bash, バージョン 4.2.46(2)-release (x86_64-redhat-linux-gnu)



#**おわりに**
Bashのコマンドや文の性能を計るために作りました。結果がでたらまた紹介します。