main: show details of the loading time

Author: akinomyoga

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
 

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

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:]]*//

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 の