Bash Infinity Frameworkとは

主な特徴は以下の通りです:

自動エラーハンドリング

名前付きパラメータ($1、$2ではなくて)

配列とマップをパラメータとして引き渡せる

try-catchの実装

独自例外のthrow

キーワードのインポート

出力を改善するためのcolorsとpowerlineキャラクターの便利なエイリアス

カラフルなロギング機能

テストライブラリ

型システムのための標準ライブラリ

関数プログラミングのためのオペレーションチェイン

オブジェクト指向プログラミングのための型システム

個人的には本格的なプログラミングにShell系を使う意義を感じないので、一部機能は過剰という気もします。
一方、特にロギング機能やテストライブラリは魅力的だと感じました。

どのように使うのか次第、という面もあります。
本家に your-script.sh というテンプレがありますのでそれを見れば分かります

your-script.sh

#!/usr/bin/env bash

## BOOTSTRAP ##
source "$( cd "${BASH_SOURCE[0]%/*}" && pwd )/lib/oo-bootstrap.sh"

## MAIN ##
# import util/log util/exception util/tryCatch util/namedParameters util/class

## YOUR CODE GOES HERE ##

適切な構造かなと思いました。特にimportで句切られてるのは好印象。
とはいえ、source の瞬間に莫大な遅延が発生するなら使いたくはありません。

期待としては「importの分量に応じて相応に重くなり、最小限利用時には相応に高速」という挙動かと思います。
logだけであればさくっとインポートできれば普段使いレベルでは十分満足です。

この記事では同ライブラリの他の側面は見てる暇も技量もないので省略します。
例えばimportした後に互換性がどうなるのか、とか、調べると面白い結果が出るかも知れません。

まず OS X El Capitan 10.11.6（15G31） iMac 5kで試します。

$ system_profiler SPHardwareDataType
Hardware:

    Hardware Overview:

      Model Name: iMac
      Model Identifier: iMac15,1
      Processor Name: Intel Core i5
      Processor Speed: 3.5 GHz
      Number of Processors: 1
      Total Number of Cores: 4
      L2 Cache (per Core): 256 KB
      L3 Cache: 6 MB
      Memory: 32 GB
      Boot ROM Version: IM151.0207.B06
      SMC Version (system): 2.23f11
      Serial Number (system): C02Q50VJFY14
      Hardware UUID: 1EBAFC14-654A-5B86-AC02-EB3F3D6472BE

使用したスクリプトは以下のとおり

log_sample.sh

#!/bin/bash
#
# See also bash-oo-framework/your-script.sh
#

if ((BASH_VERSINFO[0] < 4))
then
  echo "Use bash version 4 (or later?)"
  exit 1
fi

# http://stackoverflow.com/questions/16548528
ns1=$(date +%s%N)

## BOOTSTRAP ##
source "$( cd "${BASH_SOURCE[0]%/*}" && pwd )/bash-oo-framework/lib/oo-bootstrap.sh"

ns2=$(date +%s%N)

## MAIN ##
import util/log
# import util/log util/exception util/tryCatch util/namedParameters util/class

ns3=$(date +%s%N)

# begin: bash-oo-frameworkのREADME.mdそのまんま

# using colors:
echo "$(UI.Color.Blue)I'm blue...$(UI.Color.Default)"

# enable basic logging for this file by declaring a namespace
namespace myApp
# make the Log method direct everything in the namespace 'myApp' to the log handler called DEBUG
Log::AddOutput myApp DEBUG

# now we can write with the DEBUG output set
Log "Play me some Jazz, will ya? $(UI.Powerline.Saxophone)"

# redirect error messages to STDERR
Log::AddOutput error STDERR
subject=error Log "Something bad happened."

# reset outputs
Log::ResetAllOutputsAndFilters

# You may also hardcode the use for the StdErr output directly:
Console::WriteStdErr "This will be printed to STDERR, no matter what."

# end: bash-oo-frameworkのREADME.mdそのまんま

ns4=$(date +%s%N)

echo 'step1〜step2: ' $((($ns2 - $ns1)/1000000)) 'ms'
echo 'step2〜step3: ' $((($ns3 - $ns2)/1000000)) 'ms'
echo 'step3〜step4: ' $((($ns4 - $ns3)/1000000)) 'ms'

bash4は弊環境では (brewでbash入れた場合) /usr/local/bin/bashにありますのでshebangに頼らずに実行します。

$ /usr/local/bin/bash ./log_sample.sh
I'm blue...
[DEBUG] [log_sample.sh:37] Play me some Jazz, will ya? 🎷
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  22 ms
step2〜step3:  71 ms
step3〜step4:  26 ms

(わざわざ踏み込みませんが、このレベルだと実行速度には当然ブレがあります)

スクショも貼ってみます (上の例とは違うので値も異なります)

青かったり黄色かったり……ナイスです。おお……見事な。

また、インポート時の遅延も許容範囲のケースはあるでしょう。
ただ、すこーし遅延が体感でも感じられますので、100ms遅延でキレるユースケースには依然として向きません。
(そういうのをあんまり気にするのならshベースの高速実行フレームワークを選択するか、FPGAにでも向かうべきです)

ところで大量インポートした場合どうなるか。
本家のサンプルの一部を以下のように編集してためします。log以外は実際には使いません

# import util/log
import util/log util/exception util/tryCatch util/namedParameters util/class

$ /usr/local/bin/bash ./log_sample.sh
I'm blue...
[DEBUG] [log_sample.sh:37] Play me some Jazz, will ya? 🎷
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  18 ms
step2〜step3:  605 ms
step3〜step4:  43 ms

正直ミリ秒レベルの計測だと数回やったくらいでなんとも言えない、つーのはありますが、
起動速度としてとても高速とは言えない結果が出てきます。
HDDのキャッシュとかそういうチャチなものじゃない遅延です。

参考: 他環境での簡単な計測

さくらのVPS 1G (HHD)環境上で試した結果も見てみます。

$ lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description:    Debian GNU/Linux 7.11 (wheezy)
Release:        7.11
Codename:       wheezy

logのみimport

$ ./log_sample.sh
I'm blue...
[DEBUG] [log_sample.sh:37] Play me some Jazz, will ya? 🎷
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  9 ms
step2〜step3:  44 ms
step3〜step4:  21 ms

まるっとimport

$ ./log_sample.sh
I'm blue...
[DEBUG] [log_sample.sh:37] Play me some Jazz, will ya? 🎷
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  13 ms
step2〜step3:  589 ms
step3〜step4:  12 ms

傾向は同じです。

NVMe (高速SSD) 上のAlpine Linux (ただしKVM上) というかなり軽量な環境で計測してみます。
いやー、軽いんだよこの環境。ホントマジで。どんな結果が出るかなー

$ cat /etc/alpine-release
3.4.3
$ bash --version
GNU bash, version 4.3.42(1)-release (x86_64-alpine-linux-musl)
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>

This is free software; you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
$ git clone https://github.com/dmiyakawa/bashinf-sample.git
Cloning into 'bashinf-sample'...
remote: Counting objects: 12, done.
remote: Compressing objects: 100% (8/8), done.
remote: Total 12 (delta 4), reused 11 (delta 3), pack-reused 0
Unpacking objects: 100% (12/12), done.
Checking connectivity... done.
$ cd bashinf-sample/
$ git clone https://github.com/niieani/bash-oo-framework.git
Cloning into 'bash-oo-framework'...
remote: Counting objects: 1522, done.
remote: Total 1522 (delta 0), reused 0 (delta 0), pack-reused 1522
Receiving objects: 100% (1522/1522), 631.07 KiB | 329.00 KiB/s, done.
Resolving deltas: 100% (929/929), done.
Checking connectivity... done.
$ ./log_sample.sh
I'm blue...
DEBUG[Play me some Jazz, will ya? (YEAH)] [log_sample.sh:37]
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  0 ms
step2〜step3:  0 ms
step3〜step4:  0 ms
$ vim log_sample.sh  # ここで編集してまるっとインポートに変更
$ ./log_sample.sh
I'm blue...
DEBUG[Play me some Jazz, will ya? (YEAH)] [log_sample.sh:37]
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  0 ms
step2〜step3:  0 ms
step3〜step4:  0 ms

えっ

……

……計測にならなかった(´・ω・｀)

ちなみに ns 単位でも 0nsになるという悲惨な結果でした。むしろ繰り返すと稀に1nsを観測できるとかそういうレベル。

何か初歩的なところで間違っている可能性を疑ってるのですが……気づいた方がいらっしゃったらコメントをお願いします……

＃ (2016-08-30 17:58) 判明しました。追記を御覧ください (ワロタ)

心配なので、同NVMe上のUbuntu 14.04 LTS環境でも同様の実験をしてみます (やはりKVM)

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 14.04.5 LTS
Release:        14.04
Codename:       trusty
$ git clone https://github.com/dmiyakawa/bashinf-sample.git
Cloning into 'bashinf-sample'...
remote: Counting objects: 12, done.
remote: Compressing objects: 100% (8/8), done.
remote: Total 12 (delta 4), reused 11 (delta 3), pack-reused 0
Unpacking objects: 100% (12/12), done.
Checking connectivity... done.
$ cd bashinf-sample
$ git clone https://github.com/niieani/bash-oo-framework.git
Cloning into 'bash-oo-framework'...
remote: Counting objects: 1522, done.
remote: Total 1522 (delta 0), reused 0 (delta 0), pack-reused 1522
Receiving objects: 100% (1522/1522), 631.07 KiB | 328.00 KiB/s, done.
Resolving deltas: 100% (929/929), done.
Checking connectivity... done.
$ ./log_sample.sh
I'm blue...
[DEBUG] [log_sample.sh:37] Play me some Jazz, will ya? 🎷
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  4 ms
step2〜step3:  15 ms
step3〜step4:  4 ms
$ vim log_sample.sh
$ ./log_sample.sh
I'm blue...
[DEBUG] [log_sample.sh:37] Play me some Jazz, will ya? 🎷
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  18 ms
step2〜step3:  291 ms
step3〜step4:  5 ms

一応予想通りといえば予想通り。まるっとimportは程度の差があれ「遅い」ことは間違いないようですが、なんだったんだAlpine

Bash Infinity Frameworkの話じゃなくなってきましたので、とりあえずここまで……

今回使ったスクリプト: https://github.com/dmiyakawa/bashinf-sample

まとめ

今回の実験で、Bash Infinity Frameworkは、
普段使いのフレームワークとしてふさわしい速度で動くことが分かった。
また、あまりに高速な環境では、
dateコマンドでは信頼できる精度で速度を測れないことも分かった。
だから、やってみなくちゃ分からない。
大Qiita実験で。

追記のまとめ

以下三点追記がありますが、要するに (Bash Infinity Frameworkの話ではなく) Alpine Linux で 0ns ってなんかおかしくね、という話の結論は

「/bin/dateが/bin/busyboxを指しており、nano秒を計測できてなかった」

という結論にまとまりました。

(GNU) coreutilsのdateでも幾分早いことが期待できる結果にはなっている「かも」といったところ。
少なくとも高速化に寄与しそうな要素は結構あるようですが、さすがに「0nsとか出たらまずアホだと思え」ということになりそうです。

正直これ以上掘り下げても仕方ないので細かくは計測するつもりはないですが、油断ならんなぁと。
(もっともbusyboxでやられるのはlsでもなんでもそうなのですけどね)

御指南頂いた皆様ありがとうございました。

だから、やってみなくちゃ分からない。
大Qiita実験で。

わかれよｗ

追記 (2016-08-30 14:21)

「それにしてもAlpine早すぎるぞ」問題ですが、FBにて「straceしたら分かるんでは」とT氏よりありましたので「おおなるほど」と、strace -fでざっと見てみました。
完全に本筋から外れるので「ボトルネック」みたいな話は完全にすっ飛ばしますが実行時に外部ファイルやライブラリ・ロケール情報等を読みこんだりする(つまり余分なsyscallが発生する回数)がAlpine Linuxの方がやたら少ないのが原因、かなぁという感じです。

まず strace -f で出てくる標準エラー出力の「行数」 (雑だなぁ) だけ見ても、弊環境下では Alpine Linux 環境下で18126行、Ubuntu 環境下で49677行となりました。
3倍とはいいませんが2倍強の差。
これではもちろん具体的には何もわからないんですが、straceの結果が行数ベースでもこんだけ違ったら、事前に呼んでるsyscallの数だって全然ちげーだろ、という雑予想がまず、立ちます。

その他に、Ubuntu側では/usr/lib/locale/locale-archiveを60回かそこら読み込んだり、各種周辺の.soファイルをopen()しまくったりしてまして、
全体としてそういうのが蓄積されているんじゃないか？みたいなところかと思います。

1行ずつ読めばもっとこまけーことが分かるのは間違いないですが、興味がおありの方は是非AlpineをDockerで立てるなどしてやっていただければ良いとおもいます。
その他、何か分かったら教えてくだしまし……

思いつくのはあとは実行時のメモリマップとかそりゃぁ色々ありそうですね。
……目的がbashで簡単につかえるlogやテストフレームワークが欲しかったというだけのところから変な脱線してる。うーむｗ

あ、ちなみに……

$ strace -f ./log_sample.sh 2> /tmp/log_sample.txt
I'm blue...
step1〜step2:  0 ns
step2〜step3:  0 ns
step3〜step4:  0 ns

動じねぇなぁおいｗ

計測としてよくねーなーと思った点。
実はUbuntu 14.04 LTS環境側、他のタスクも結構走っているという意味では「純粋」な環境じゃないんですよね。syscallがたくさん出てくるということの他に、その結果としてタスク切り替えがおきて、動いていないとはいえプロセススケジューラレベルのなんやかやで持って行かれてたのかもなぁと。少なくとも「公平」な環境じゃないですねぇ……反省

追記 (2016-08-30 16:51)

FBよりlibcからして違うでねーの、というコメントも頂きました。そもそもglibcじゃ、ないんですね

というわけでshared objectsの呼ばれ方をそういう目で見るとなるほど。"/lib/x86_64-linux-gnu/libc.so.6" をAlpine Linuxでは一切open()してません。

# Alpine
$ grep ".so" /tmp/log_sample.txt  | grep open
open("/lib/libreadline.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/usr/local/lib/libreadline.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/usr/lib/libreadline.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/lib/libncursesw.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/usr/local/lib/libncursesw.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/usr/lib/libncursesw.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/tmp/bashinf-sample/bash-oo-framework/lib/UI/Console.sh", O_RDONLY) = 3
open("/tmp/bashinf-sample/bash-oo-framework/lib/UI/Console.sh", O_RDONLY) = 3
[pid  5962] open("/tmp/stored_exception_source.5886.XXXXadhFIl", O_RDWR|O_CREAT|O_EXCL, 0600) = 3

# Ubuntu
$ grep ".so" /tmp/log_sample.txt | sort | uniq
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3
open("/tmp/bashinf-sample/bash-oo-framework/lib/UI/Console.sh", O_RDONLY) = 3
[pid 24868] <... read resumed> "    declare json=$(this forEach "..., 128) = 70
[pid 24868] <... read resumed> "    @return:value \"[${json%,*}]\""..., 128) = 33
[pid 24868] <... read resumed> "/tmp/stored_exception_source.248"..., 128) = 46
[pid 24869] access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
[pid 24869] access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
[pid 24869] open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
...
(なんがーい)
...
# 面倒なのでwc -lにしちゃうわ
$ grep ".so" /tmp/log_sample.txt | wc -l
392

原因は多岐に渡るはずですが、とりあえず本記事はBash Infinity Frameworkについての記事ですのでそれだけは忘れませんように。

追記 (2016-08-30 17:59)

またしてもFBから。「何か初歩的なところで間違っている可能性」をド直球でした。

$ ls -l /bin/date
lrwxrwxrwx    1 root     root            12 Aug 15 14:25 /bin/date -> /bin/busybox

orz

そして、busyboxのdateの+%Nに対応してなかった、ということのようです。

さぁ気を取り直して、sudo apk add --update coreutilsをしてから再挑戦……！

$ date +%s%N
1472547731224701882
$ date +%s%N
1472547731728715761
$ ./log_sample.sh
I'm blue...
DEBUG[Play me some Jazz, will ya? (YEAH)] [log_sample.sh:37]
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  14 ms
step2〜step3:  37 ms
step3〜step4:  12 ms
$ vim log_sample.sh  # てんこもり
$ ./log_sample.sh
I'm blue...
DEBUG[Play me some Jazz, will ya? (YEAH)] [log_sample.sh:37]
Something bad happened.
This will be printed to STDERR, no matter what.
step1〜step2:  12 ms
step2〜step3:  226 ms
step3〜step4:  4 ms

200ms出てるのだから「体感」しているはずなんだが……気付かず。これはこれでアホだな

このレベルでもUbuntuより早い「かも」という結果は出るようす。このレベルになるともう少しきっちり実験しないと確信は持てないかな……

はずかしい(｡>﹏<｡)

Bash Infinity Framework の起動速度を見る