diff --git a/ble.pp b/ble.pp index eeded808..5dd6bdf0 100644 --- a/ble.pp +++ b/ble.pp @@ -6,14 +6,40 @@ #%[leakvar = ""] #%#---------------------------------------------------------------------------- #%if measure_load_time +_ble_init_measure_prev= +_ble_init_measure_section= +function ble/init/measure/section { + local now=${EPOCHREALTIME:-$(date +'%s.%N')} + + local s=${now%%[!0-9]*} u=000000 + if [[ $s != "$now" ]]; then + u=${now##*[!0-9]}000000 + u=${u::6} + fi + local stime=$s.$u time=$((s*1000000+10#0$u)) + + if [[ $_ble_init_measure_section ]]; then + local elapsed=$((time-_ble_init_measure_prev)) + s=$((elapsed/1000)) + u=00$((elapsed%1000)) + u=${u:${#u}-3} + elapsed=$s.${u}ms + builtin printf '[ble.sh init %s] %s done (%s)\n' "$stime" "$_ble_init_measure_section" "$elapsed" >&2 + else + builtin printf '[ble.sh init %s] start\n' "$stime" >&2 + fi + + _ble_init_measure_section=$1 + _ble_init_measure_prev=$time +} _ble_debug_measure_fork_count=$(echo $BASHPID) -TIMEFORMAT='[Elapsed %Rs; CPU U:%Us S:%Ss (%P%%)]' +TIMEFORMAT=' [Elapsed %Rs; CPU U:%Us S:%Ss (%P%%)]' function ble/debug/measure-set-timeformat { local title=$1 opts=$2 local new=$(echo $BASHPID) local fork=$(((new-_ble_debug_measure_fork_count-1)&0xFFFF)) _ble_debug_measure_fork_count=$new - TIMEFORMAT="[Elapsed %Rs; CPU U:%Us S:%Ss (%P%%)] $title" + TIMEFORMAT=" [Elapsed %Rs; CPU U:%Us S:%Ss (%P%%)] $title" [[ :$opts: != *:nofork:* ]] && TIMEFORMAT=$TIMEFORMAT" ($fork forks)" } @@ -60,9 +86,9 @@ function ble/util/print { printf '%s\n' "$1"; } # #%if measure_load_time -echo "ble.sh: $EPOCHREALTIME load start" >&2 +ble/init/measure/section 'parse' time { -echo "ble.sh: $EPOCHREALTIME parsed" >&2 +ble/init/measure/section 'source' # load_time (2015-12-03) # core 12ms # decode 10ms @@ -2625,6 +2651,9 @@ function ble-attach { fi [[ ! $_ble_attached ]] || return 0 +#%if measure_load_time + ble/init/measure/section 'prompt' +#%end _ble_attached=1 BLE_ATTACHED=1 @@ -2694,6 +2723,10 @@ function ble-attach { ble_attach_first_prompt=1 \ ble/canvas/panel/render # 42ms ble/util/buffer.flush # 0.2ms +#%if measure_load_time + ble/util/print >&2 + ble/init/measure/section 'bind' +#%end #%if leakvar ble/debug/leakvar#check $"leakvar" A6-edit @@ -2746,6 +2779,9 @@ function ble-attach { # Note: ble-decode/{initialize,reset-default-keymap} 内で # info を設定する事があるので表示する。 ble/edit/info/default +#%if measure_load_time + ble/init/measure/section 'idle' +#%end #%if leakvar ble/debug/leakvar#check $"leakvar" A11-info #%end.i @@ -3150,9 +3186,9 @@ function ble/base/sub:lib { return 0; } # do nothing fi #%if measure_load_time -ble/debug/measure-set-timeformat Total nofork; } +ble/debug/measure-set-timeformat 'Total' nofork; } _ble_init_exit=$? -echo "ble.sh: $EPOCHREALTIME load end" >&2 +[[ ${BLE_ATTACHED-} ]] || ble/init/measure/section 'wait' ble/util/setexit "$_ble_init_exit" #%end diff --git a/docs/ChangeLog.md b/docs/ChangeLog.md index 255565e5..c674fa79 100644 --- a/docs/ChangeLog.md +++ b/docs/ChangeLog.md @@ -304,6 +304,7 @@ - global: rename `ret` not used as `REPLY` `#D2300` 86cbf78e - global: avoid raw word splitting `#D2309` b55c4003 - global: use `ble/util/assign` in more places `#D2312` xxxxxxxx +- main: show details of the loading time (motivated by tessus, Darukutsu) `#D2313` xxxxxxxx # ble-0.4.0-devel3 diff --git a/make_command.sh b/make_command.sh index 7cbfcff2..5a2e5758 100755 --- a/make_command.sh +++ b/make_command.sh @@ -610,6 +610,7 @@ function sub:scan { \Z\(ble/builtin/bind\|ble/builtin/bind/\*\|bind\|ble/decode/read-inputrc/test\)Zd \Ztitle=['\''"]([^"]*: )?bind \(ble\.sh\)['\''"]Zd \Zwarning: readline \\"bind -x\\" does not supportZd + \Zble/init/measure/section '\''bind'\''Zd g' sub:scan/builtin 'read' | sed -E 'h;s/'"$_make_rex_escseq"'//g;s/^[^:]*:[0-9]+:[[:blank:]]*// diff --git a/note.txt b/note.txt index c48e147a..00bdef05 100644 --- a/note.txt +++ b/note.txt @@ -7730,6 +7730,15 @@ bash_tips 2024-12-31 + * main: 初期化時刻の表示 (motivated by tessus, Darukutsu) [#D2313] + https://github.com/akinomyoga/ble.sh/issues/340 + https://forum.atuin.sh/t/atuin-bash-and-ble-sh/175/26?u=akinomyoga + + 議論に上る度に修正して自分で計算してまた元に戻すのは面倒なので、parse, + load, attach, prompt, bind の一連の処理の時間も全て計測して表示する事にした。 + idle についてはユーザーが勘違いしそうなので積極的には表示しない。必要であれ + ば自分で書き換えて表示して使う事にする。 + * global: ble/util/assign をもっと広く使う [#D2312] 初期化の段階で $() を使っていた箇所があるが、もっと早く ble/util/assign の