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

はじめに

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

機能概要

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

shスクリプトと使用方法

【shスクリプト】

/proc/uptime版

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版

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

【使用方法】

#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

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

実行結果

============================================
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で基本統計量を計算する

環境

ホスト　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のコマンドや文の性能を計るために作りました。結果がでたらまた紹介します。