From 2b28beceb43a107428bfc8a8d864fade7750526d Mon Sep 17 00:00:00 2001 From: Koichi Murase Date: Mon, 24 Jan 2022 19:29:07 +0900 Subject: [PATCH] exec: measure execution times * todo: blerc: new bleopts * todo: ChangeLog * todo: contrib README.md --- README-ja_JP.md | 7 + README.md | 7 + blerc | 19 +++ contrib | 2 +- docs/ChangeLog.md | 23 ++-- note.txt | 106 +++++++++++++++ src/edit.sh | 326 +++++++++++++++++++++++++++++++++++++++++++--- src/util.sh | 8 +- 8 files changed, 466 insertions(+), 32 deletions(-) diff --git a/README-ja_JP.md b/README-ja_JP.md index 8e1af745..8abcf862 100644 --- a/README-ja_JP.md +++ b/README-ja_JP.md @@ -324,6 +324,13 @@ bleopt prompt_eol_mark='⏎' bleopt exec_errexit_mark= # Tip: 代わりに他の文字列をご指定頂くこともできます。 bleopt exec_errexit_mark=$'\e[91m[error %d]\e[m' + +# コマンド実行時間マーカー "[ble: elapsed 1.203s (CPU 0.4%)]" の無効化 +bleopt exec_elapsed_mark= +# Tip: 代わりに別の文字列をご指定いただくこともできます。 +bleopt exec_elapsed_mark=$'\e[94m[%ss (%s %%)]\e[m' +# Tip: マーカーを表示する条件を変更することも可能です。 +bleopt exec_elapsed_enabled='sys+usr>=10*60*1000' # 例: 合計CPU時間が 10 分以上の時に表示 ``` ## 2.3 曖昧文字幅 diff --git a/README.md b/README.md index b70d391d..a9a53d82 100644 --- a/README.md +++ b/README.md @@ -302,6 +302,13 @@ bleopt prompt_eol_mark='⏎' bleopt exec_errexit_mark= # Tip: you may instead specify another string: bleopt exec_errexit_mark=$'\e[91m[error %d]\e[m' + +# Disable elapsed-time marker like "[ble: elapsed 1.203s (CPU 0.4%)]" +bleopt exec_elapsed_mark= +# Tip: you may instead specify another string +bleopt exec_elapsed_mark=$'\e[94m[%ss (%s %%)]\e[m' +# Tip: you may instead change the threshold of showing the mark +bleopt exec_elapsed_enabled='sys+usr>=10*60*1000' # e.g. ten minutes for total CPU usage ``` ## 2.3 CJK Width diff --git a/blerc b/blerc index 2c8ef2c3..ae6b0ba3 100644 --- a/blerc +++ b/blerc @@ -212,6 +212,25 @@ #bleopt exec_errexit_mark=$'\e[91m[ble: exit %d]\e[m' +## "exec_elapsed_mark" specifies the format of the command execution time +## report. It takes two arguments: the first is the string that explains the +## elapsed time, and the second is a number that represents the percentage of +## CPU core usage. "exec_elapsed_enabled" specifies the condition that the +## command execution time report is displayed after the command execution. The +## condition is expressed by an arithmetic expression, where a non-zero result +## causes displaying the report. In the arithmetic expression, variables +## "real", "{usr,sys}{,_self,_child}", and "cpu" can be used. "real" +## represents the elapsed time. "usr" and "sys" represent the user and system +## time, respectively. The suffixes "_self" and "_child" represent the part +## consumed in the main shell process and the other child processes including +## subshells and external programs, respectively. "cpu" represents the +## percentage of the CPU core usage in integer, which can be calculated by +## "(usr+sys)*100/real". The other values are all in unit of milliseconds. + +#bleopt/declare -v exec_elapsed_mark $'\e[94m[ble: elapsed %s (CPU %s%%)]\e[m' +#bleopt/declare -v exec_elapsed_enabled 'usr+sys>=10000' + + ## The following setting controls the exit when jobs are remaining. When an ## empty string is set, the shell will never exit with remaining jobs through ## widgets. When an non-empty value is set, the shell will exit when exit is diff --git a/contrib b/contrib index 9fd72ecb..bb09bcb9 160000 --- a/contrib +++ b/contrib @@ -1 +1 @@ -Subproject commit 9fd72ecb2c6ebc62aadcea47edd7c0d699b8f4c4 +Subproject commit bb09bcb9107ad07ee228ece3216efc98bdd4daa8 diff --git a/docs/ChangeLog.md b/docs/ChangeLog.md index 7275c2b9..d6092d53 100644 --- a/docs/ChangeLog.md +++ b/docs/ChangeLog.md @@ -82,13 +82,14 @@ - menu (menu-style:desc): support multicolumns (motivated by Shahabaz-Bagwan) `#D1686` 231dc39 - menu (menu-style:desc): fix not working `bleopt menu_desc_multicolumn_width=` `#D1727` 2140d1e - term: let DECSCUSR pass through terminal multiplexers (motivated by cmplstofB) `#D1697` a3349e4 - - util: refactor `_ble_term_TERM` `#D1746` 0000000 + - util: refactor `_ble_term_TERM` `#D1746` 63fba6b - complete: requote for more compact representations on full completions `#D1700` a1859b6 - complete: improve support for `declare` and `[[ ... ]]` `#D1701` da38404 - syntax: fix completion and highlighting of `declare` with assignment arguments `#D1704` `#D1705` e12bae4 - cmdspec: refactor `{mandb => cmdspec}_opts` `#D1706` `#D1707` 0786e92 - complete (menu-style:align): refactor `complete_menu_align => menu_align_{min,max}` (motivated by banoris) `#D1717` 22a2449 -- prompt: support `bleopt prompt_command_changes_layout` `#D1750` 0000000 +- prompt: support `bleopt prompt_command_changes_layout` `#D1750` e199bee +- exec: measure execution times `#D1756` 0000000 ## Changes @@ -137,8 +138,8 @@ - highlight (`wtype=CTX_CMDI`): check alias names before shell expansions `#D1715` d6242a7 - util (`ble/is-alias`): fix a bug of unredirected error messages for bash-3.2 (fixup d6242a7) `#D1730` 31372cb - edit (`history_share`): update history on `discard-line` (reported by SuperSandro2000) `#D1742` 8dbefe0 -- canvas: do not insert explicit newlines on line folding if possible (reported by banoris) `#D1745` 02b9da6 0000000 -- edit (`ble-bind -x`): preserve multiline prompts on execution of `bind -x` commands `#D1755` 0000000 +- canvas: do not insert explicit newlines on line folding if possible (reported by banoris) `#D1745` 02b9da6 dc3827b +- edit (`ble-bind -x`): preserve multiline prompts on execution of `bind -x` commands (requested by SuperSandro2000) `#D1755` 7d05a28 ## Fixes @@ -295,15 +296,15 @@ - menu (`menu-style:desc`): work around xenl quirks for relative cursor movements (reported by telometto) `#D1728` 3e136a6 - global: work around the arithmetic syntax error of `10#` in Bash-5.1 `#D1734` 7545ea3 - global: adjust implementations for Bash 5.2 `patsub_replacement` `#D1738` 4590997 - - global: work around compat42 quoting of "${v/pat/"$rep"}" `#D1751` 0000000 - - prompt: fix a bug of ble/prompt/print redundantly quoting '$' `#D1752` 0000000 - - global: identify bash-4.2 bug that internal quoting of `${v/%$empty/"$rep"}` remains `#D1753` 0000000 - - global: work around `shopt -s compat42` `#D1754` 0000000 + - global: work around `compat42` quoting of `"${v/pat/"$rep"}"` `#D1751` a75bb25 + - prompt: fix a bug of `ble/prompt/print` redundantly quoting `$` `#D1752` a75bb25 + - global: identify bash-4.2 bug that internal quoting of `${v/%$empty/"$rep"}` remains `#D1753` a75bb25 + - global: work around `shopt -s compat42` `#D1754` a75bb25 - global (`ble/builtin/*`): work around `set -eu` in NixOS initialization (reported by SuperSandro2000) `#D1743` 001c595 - util, edit, contrib: add support for `bash-preexec` (motivated by SuperSandro2000) `#D1744` e85f52c -- main: check `IN_NIX_SHELL` to inactivate ble.sh in nix-shell `#D1747` 0000000 -- canvas: test the terminal for the sequence of clearing `DECSTBM` `#D1748` 0000000 -- main: check `/dev/tty` on startup (reported by andychu) `#D1749` 0000000 +- main: check `IN_NIX_SHELL` to inactivate ble.sh in nix-shell (suggested by SuperSandro2000) `#D1747` b4bd955 +- canvas: test the terminal for the sequence of clearing `DECSTBM` `#D1748` 4b1601d +- main: check `/dev/tty` on startup (reported by andychu) `#D1749` 711c69f ## Internal changes and fixes diff --git a/note.txt b/note.txt index acff6316..5d464791 100644 --- a/note.txt +++ b/note.txt @@ -1350,6 +1350,7 @@ bash_tips 2022-01-23 + 683 にも unresolved patch suggestion がある。 https://github.com/scop/bash-completion/pull/687#discussion_r790203991 : IFS=$'\0' in mount https://github.com/scop/bash-completion/pull/687#discussion_r790203132 : mechanism of save/restore shopt @@ -1731,8 +1732,51 @@ bash_tips ToDo ------------------------------------------------------------------------------- +2022-01-31 + + * rsync --no-while-f[TAB] で説明が一緒に挿入されてしまう。DATA を挿入している + のだろうか。。或いは、単一確定の場合に postprocess が走っていなくて直接補完 + されている。後で確認する必要がある。 + + * bash-completion _services が failglob で問題を起こしてい + る。_comp_init_set_up_service_completions も駄目。うーん。failglob ではある + がこれは自分が修正している途中の物ではない新しい物だろうか? →これは既に + fix-failglob　の中に含まれていた。 + 2022-01-23 + * コマンドのログ機能を作成する。 + + 特定のファイルに情報を書き込む。 + + 同時に複数の書き込みがあった場合に混ざり合う危険性がある。滅多に起こらない + と思いたいがちゃんと防止策は作っておく必要がある。例えばシェル毎に履歴を記 + 録して終了する時に合成するという手が考えられる。合成自体が衝突する自体を防 + ぐために mkdir/rmdir を使うのが一つの手である。 + + コマンドにはコマンド実行前とコマンド実行後の二つに分けて結果を書き込みたい + という欲求がある。という事を考えると、 + + $ printf '%x/%s/%s.e%s\n' $(printf '%(%s)T' -1) "$HOSTNAME" $$ "$LINENO" + + * バックグラウンドのジョブの状態はどの様に記録するのか。うーん。ジョブに関 + しては一応 ble.sh の中で追跡はしている。それに従って終端を幾らか荒い尺度 + で検出する事はできる。しかし正確な時間は分からない。 + + プロンプトを表示した時刻も記録しておくと良い様に思われる。しかしそうなる + と大量の記録が残ってしまう事になるのではないか。うーん。プロンプトを表示 + した時刻に関しては別に全てを記録する必要はない。前回のプロンプトの表示時 + 刻だけ覚えておいて、ジョブ変化を検出した時にその情報を備考として乗せるだ + けで良いのである。 + + * 記録する情報は以下の通り。 + + cmd, pwd, 終了ステータス(PIPESTATUS), 各種時刻情報, files(自動補完用), 構 + 文解析情報(後で単語を抽出する為。というか単語の範囲だけで良い). + + これを使って処理するのはもしかしたら外部プログラムに頼らなければならない + かもしれない。 + * 元々存在した DEBUG trap を保持する * bash-preexec に API 安定化のお願いをする。 @@ -5900,6 +5944,68 @@ bash_tips 2022-01-24 + * edit: コマンド実行時間計測 [#D1756] + + 前から気になっていたので実装する。 + + * time を用いた計測? 少なくとも msec の精度は存在する。prologue にかかる時 + 間などは気になるが。prologue は含めずに計測するのが良いだろう。 + + + 現在の gexec の構造を何処まで変更できるかについて確認しなければならない。 + 現在の構造に修正したのは 014d17e6 (#D0465)である。うーん。eval を跨ぐと + $_ が継承されない? と思ったが prologue に関しては同じ eval に入れなくても + 大丈夫に見える。以下のコマンドを各 bash version で試したがちゃんと動いて + いる。 + + $ { echo hello world; time builtin eval 'echo "[$_]"'; echo $_; } + + うーん。分かった。prologue を同じ eval の中に入れるのは set -v の時の出力 + を最低限に抑える為である → 書き換えた。一応ちゃんと $_ 及び $? が復元で + きている事を確かめた。 + + うーん。ble/util/clock だとか ble/bin/date +%s%6N だとかに頼る方法を考えて + いたが、time の結果を読み取っている現状では tot をそのまま参照すれば良い気 + がする。開始時刻に関しては date または printf または SECONDS を用いて取得す + れば良い → 最終的にはやはり ble/util/clock または date +%s%6N に頼る事にし + た。それを tot を用いて補正する。 + + * SECONDS, EPOCHREALTIME, EPOCHSECONDS を readonly するという事? EPOCH* に + ついては流石に間違えて上書きしたりする事はないと思われる。SECONDS は + ble/util/clock の初期化時に readonly する事にした。EPOCHSECONDS はどうせ + 使っていないので関係ない。 + + * done: カスタマイズインターフェイスについて考えた方が良い気がする。現状で + 既存の errexit とどうくっつけるのかというのが問題である。というより、本当 + は色分けをしたりしたい所だが、現状 errexit の設計が固定文字列になっている + ので、勝手に弄る余地がなくなってしまっている。 + + 或いは既定値の時にはくっつけるという操作をするというのでも良いかもしれな + い? と思ったがそれも変である。或いは、もっと別枠の設定を用意するというの + も手なのかもしれない→うーん。両方とも無効化して自前で書くというのが良い + 気がする。という事を考えたら、現状では exec_errexit_mark と同様に + exec_elapsed_mark を定義すれば良い。 + + * done: contrib README.md + * done: ChangeLog + * done: blerc: new bleopts + * done: wiki: new bleopts + + x 外部コマンドの時間が計れていない? と思ったが単に cxxmatrix に対して端末が + 遅いだけなのであった。多分測れている。子シェルを合計するかしないかの設定 + があった気がしたけれど、それは多分 times であって関係ないのだ。一応 times + を使えば real 及び sys の子プロセスの内訳も見られる気がする…が BG で動い + ている物が加算されるのかは謎である。 + + →うーん。times はジョブが終了した瞬間に加算されるので、bg のジョブが丁度 + 終了したりすると、現在実行しているコマンドの shell/sys の値を評価できなく + なる。そもそも time で取れている情報の筈なので関係ない気もする。。と思っ + たが、シェル本体と子プロセスの時間を区別するのには使えるのかもしれない。 + つまり自プロセスの処理時間を取得するのには使える。 + + x EOF marker が動かなくなっている。確認する必要がある。と思ったがこれは単純 + に 2 が /dev/null に繋がっていたというだけの話だった。OK + * edit: bind -x 関数の呼び出しに際しての画面クリアの振る舞いについて (motivated by SuperSandro2000) [#D1755] https://github.com/akinomyoga/blesh-contrib/issues/6#issuecomment-1020165711 diff --git a/src/edit.sh b/src/edit.sh index 88c653df..bc1a5e08 100644 --- a/src/edit.sh +++ b/src/edit.sh @@ -235,6 +235,9 @@ bleopt/declare -v accept_line_threshold 5 ## この変数が空の時、終了ステータスは表示しません。 bleopt/declare -v exec_errexit_mark $'\e[91m[ble: exit %d]\e[m' +bleopt/declare -v exec_elapsed_mark $'\e[94m[ble: elapsed %s (CPU %s%%)]\e[m' +bleopt/declare -v exec_elapsed_enabled 'usr+sys>=10000' + ## @bleopt line_limit_length ## 一括挿入時のコマンドライン文字数の上限を指定します。 ## 0以下の値は文字数に制限を与えない事を示します。 @@ -5399,6 +5402,222 @@ function ble/builtin/exit { function exit { ble/builtin/exit "$@"; } +# start time - end time - end + +# time Command による計測 +_ble_exec_time_TIMEFILE=$_ble_base_run/$$.exec.time +_ble_exec_time_TIMEFORMAT= +_ble_exec_time_tot= +_ble_exec_time_usr= +_ble_exec_time_sys= +function ble/exec/time#adjust-TIMEFORMAT { + if [[ ${TIMEFORMAT+set} ]]; then + _ble_exec_time_TIMEFORMAT=$TIMEFORMAT + else + builtin unset -v _ble_exec_time_TIMEFORMAT + fi + TIMEFORMAT='%R %U %S' +} +function ble/exec/time#restore-TIMEFORMAT { + if [[ ${_ble_exec_time_TIMEFORMAT+set} ]]; then + TIMEFORMAT=$_ble_exec_time_TIMEFORMAT + else + builtin unset -v 'TIMEFORMAT[0]' + fi + local tot usr sys dummy + IFS=' ' builtin read -r tot usr sys dummy < "$_ble_exec_time_TIMEFILE" + ((_ble_exec_time_tot=10#0${tot//[!0-9]})) + ((_ble_exec_time_usr=10#0${usr//[!0-9]})) + ((_ble_exec_time_sys=10#0${sys//[!0-9]})) +} + +_ble_exec_time_TIMES=$_ble_base_run/$$.exec.times +_ble_exec_time_usr_self= +_ble_exec_time_sys_self= +function ble/exec/time/times.parse-time { + local rex='^([0-9]+m)?([0-9]*)([^0-9ms][0-9]{3})?s?$' + [[ $1 =~ $rex ]] || return 1 + local min=$((10#0${BASH_REMATCH[1]%m})) + local sec=$((10#0${BASH_REMATCH[2]})) + local msc=$((10#0${BASH_REMATCH[3]#?})) + ((ret=(min*60+sec)*1000+msc)) + return 0 +} 2>/dev/tty +function ble/exec/time/times.start { + builtin times >| "$_ble_exec_time_TIMES" +} +function ble/exec/time/times.end { + builtin times >> "$_ble_exec_time_TIMES" + local times + ble/util/readfile times "$_ble_exec_time_TIMES" + ble/string#split-words times "$times" + + _ble_exec_time_usr_self= + _ble_exec_time_sys_self= + local ret= t1 t2 + ble/exec/time/times.parse-time "${times[0]}" && t1=$ret && + ble/exec/time/times.parse-time "${times[4]}" && t2=$ret && + ((_ble_exec_time_usr_self=t2>t1?t2-t1:0, + _ble_exec_time_usr_self>_ble_exec_time_usr&&( + _ble_exec_time_usr_self=_ble_exec_time_usr))) + ble/exec/time/times.parse-time "${times[1]}" && t1=$ret && + ble/exec/time/times.parse-time "${times[5]}" && t2=$ret && + ((_ble_exec_time_sys_self=t2>t1?t2-t1:0, + _ble_exec_time_sys_self>_ble_exec_time_sys&&( + _ble_exec_time_sys_self=_ble_exec_time_sys))) + return 0 +} +function ble/exec/time#mark-enabled { + # Note: exec_elapsed_enabled から参照できる変数 + local real=$_ble_exec_time_tot + local usr=$_ble_exec_time_usr usr_self=$_ble_exec_time_usr_self + local sys=$_ble_exec_time_sys sys_self=$_ble_exec_time_sys_self + local usr_child=$((usr-usr_self)) + local sys_child=$((sys-sys_self)) + local cpu=$((real>0?(usr+sys)*100/real:0)) + ((bleopt_exec_elapsed_enabled)) +} + +_ble_exec_time_beg= +_ble_exec_time_end= +_ble_exec_time_ata= +function ble/exec/time#start { + # 初回呼び出しで初期化 + + if ((_ble_bash>=50000)); then + _ble_exec_time_EPOCHREALTIME_delay=0 + _ble_exec_time_EPOCHREALTIME_beg= + _ble_exec_time_EPOCHREALTIME_end= + function ble/exec/time#start { + # EPOCHREALTIME の時は精度が高いので、正確に計測するため直接 + # prologue/epilogue に記述する + ble/exec/time/times.start + _ble_exec_time_EPOCHREALTIME_beg= + _ble_exec_time_EPOCHREALTIME_end= + } + function ble/exec/time#end { + local beg=${_ble_exec_time_EPOCHREALTIME_beg//[!0-9]} + local end=${_ble_exec_time_EPOCHREALTIME_end//[!0-9]} + ((beg+=delay,beg>end)) && beg=$end + _ble_exec_time_beg=$beg + _ble_exec_time_end=$end + _ble_exec_time_ata=$((end-beg)) + _ble_exec_time_LINENO=$LINENO + ble/exec/time/times.end + } + + function ble/exec/time#calibrate.restore-lastarg { + _ble_exec_time_EPOCHREALTIME_beg=$EPOCHREALTIME + return "$_ble_edit_exec_lastexit" + } + function ble/exec/time#calibrate.save-lastarg { + _ble_exec_time_EPOCHREALTIME_end=$EPOCHREALTIME + ble/exec/time#adjust-TIMEFORMAT + } + function ble/exec/time#calibrate { + local _ble_edit_exec_lastexit=0 + local _ble_edit_exec_lastarg=hello + local _ble_exec_time_EPOCHREALTIME_beg= + local _ble_exec_time_EPOCHREALTIME_end= + local _ble_exec_time_tot= + local _ble_exec_time_usr= + local _ble_exec_time_sys= + local TIMEFORMAT= + + # create a script + local script1='ble/exec/time#calibrate.restore-lastarg "$_ble_edit_exec_lastarg"' + local script2='{ ble/exec/time#calibrate.save-lastarg; } &>/dev/null' + local script=$script1$_ble_term_nl$script2$_ble_term_nl + + # make a histogram + local -a hist=() + local i + for i in {00..99}; do + { builtin eval -- "$script" 2>&$_ble_util_fd_stderr; } 2>| "$_ble_exec_time_TIMEFILE" + ble/exec/time#restore-TIMEFORMAT + local beg=${_ble_exec_time_EPOCHREALTIME_beg//[!0-9]} + local end=${_ble_exec_time_EPOCHREALTIME_end//[!0-9]} + ((hist[end-beg]++)) + done + + # calculate weighted average + local -a keys; keys=("${!hist[@]}") + keys=("${keys[@]::(${#keys[@]}+1)/2}") # Remove outliers + local s=0 n=0 t + for t in "${keys[@]}"; do ((s+=t*hist[t],n+=hist[t])); done + ((_ble_exec_time_EPOCHREALTIME_delay=s/n)) + } + ble/exec/time#calibrate + builtin unset -f ble/exec/time#calibrate + builtin unset -f ble/exec/time#calibrate.restore-lastarg + builtin unset -f ble/exec/time#calibrate.save-lastarg + + else + _ble_exec_time_CLOCK_base=0 + _ble_exec_time_CLOCK_beg= + _ble_exec_time_CLOCK_end= + function ble/exec/time#end.adjust { + # 辻褄合わせ + ((_ble_exec_time_beg/dev/null && [[ $ret ]]; then + function ble/exec/time#start { + ble/exec/time/times.start + _ble_exec_time_CLOCK_beg= + _ble_exec_time_CLOCK_end= + ble/util/assign _ble_exec_time_CLOCK_beg 'ble/bin/date +%s%6N' + } + function ble/exec/time#end { + ble/util/assign _ble_exec_time_CLOCK_end 'ble/bin/date +%s%6N' + local prev_end=$_ble_exec_time_end + _ble_exec_time_beg=$_ble_exec_time_CLOCK_beg + _ble_exec_time_end=$_ble_exec_time_CLOCK_end + _ble_exec_time_ata=$((_ble_exec_time_tot*1000)) + ble/exec/time#end.adjust + ble/exec/time/times.end + } + fi ;; + esac + fi + + ble/exec/time#start +} + ## @fn ble-edit/exec:$bleopt_internal_exec_type/process ## 指定したコマンドを実行します。 ## @param[in,out] _ble_edit_exec_lines @@ -5582,6 +5801,9 @@ function ble-edit/exec:gexec/.end { ble-edit/bind/.tail # flush will be called here } +## @fn ble-edit/exec:gexec/.prologue command +## @param[in] command +## 次に実行するコマンド。_ble_edit_exec_BASH_COMMAND に記録する。 function ble-edit/exec:gexec/.prologue { _ble_edit_exec_inside_prologue=1 local IFS=$_ble_term_IFS @@ -5598,28 +5820,51 @@ function ble-edit/exec:gexec/.prologue { ble-edit/exec/print-PS0 >&$_ble_util_fd_stdout 2>&$_ble_util_fd_stderr ((++_ble_edit_CMD)) + ble/exec/time#start ble-edit/exec/restore-BASH_REMATCH +} + +## @fn ble-edit/exec:gexec/.restore-lastarg lastarg +## @param[dummy] lastarg +## この引数は続くコマンドが $_ で参照する為の物なのでこの関数自身は利用しな +## い。 +function ble-edit/exec:gexec/.restore-lastarg { ble/base/restore-bash-options ble/base/restore-POSIXLY_CORRECT ble/base/restore-builtin-wrappers - builtin eval -- "$_ble_bash_FUNCNEST_restore" # これ以降関数は呼び出せない + + # Note: これ以降関数は呼び出せない。但し一重までなら関数を呼び出せるので + # ble-edit/exec:gexec/.restore-lastarg だけなら問題ない筈。 + builtin eval -- "$_ble_bash_FUNCNEST_restore" _ble_edit_exec_TRAPDEBUG_enabled=1 _ble_edit_exec_inside_userspace=1 + _ble_exec_time_EPOCHREALTIME_beg=$EPOCHREALTIME return "$_ble_edit_exec_lastexit" # set $? } &>/dev/null # set -x 対策 #D0930 -function ble-edit/exec:gexec/.save-last-arg { - _ble_edit_exec_lastarg=$_ _ble_edit_exec_lastexit=$? _ble_edit_exec_PIPESTATUS=("${PIPESTATUS[@]}") +function ble-edit/exec:gexec/.save-lastarg { + _ble_exec_time_EPOCHREALTIME_end=$EPOCHREALTIME \ + _ble_edit_exec_lastexit=$? \ + _ble_edit_exec_lastarg=$_ \ + _ble_edit_exec_PIPESTATUS=("${PIPESTATUS[@]}") _ble_edit_exec_inside_userspace= _ble_edit_exec_TRAPDEBUG_enabled= - builtin eval -- "$_ble_bash_FUNCNEST_adjust" # 他の関数呼び出しよりも先 + + # Note: 他の関数呼び出しよりも先。FUNCNEST の効果があるのは最低でも + # FUNCNEST=1 なので一重なら関数はいつでも呼び出せる。なのでこの関数 + # .save-lastarg 自体の呼び出しは問題ない。 + builtin eval -- "$_ble_bash_FUNCNEST_adjust" ble/base/adjust-bash-options + ble/exec/time#adjust-TIMEFORMAT return "$_ble_edit_exec_lastexit" } function ble-edit/exec:gexec/.epilogue { - _ble_edit_exec_lastexit=$? # lastexit + # Note: $_ は同じ eval の中でないと取れないのでここでは読み取らない。 + _ble_exec_time_EPOCHREALTIME_end=${_ble_exec_time_EPOCHREALTIME_end:-$EPOCHREALTIME} \ + _ble_edit_exec_lastexit=$? _ble_edit_exec_inside_userspace= _ble_edit_exec_TRAPDEBUG_enabled= - builtin eval -- "$_ble_bash_FUNCNEST_adjust" # 他の関数呼び出しよりも先 + # Note: 他の関数呼び出しよりも先 + builtin eval -- "$_ble_bash_FUNCNEST_adjust" ble/base/adjust-builtin-wrappers-1 if ((_ble_edit_exec_lastexit==0)); then _ble_edit_exec_lastexit=$_ble_edit_exec_INT @@ -5637,23 +5882,59 @@ function ble-edit/exec:gexec/.epilogue { ble-edit/adjust-READLINE ble-edit/adjust-PS1 ble-edit/exec/save-BASH_REMATCH + ble/exec/time#restore-TIMEFORMAT + ble/exec/time#end ble/util/reset-keymap-of-editing-mode ble-edit/exec/.adjust-eol _ble_edit_exec_inside_prologue= + ble/util/buffer.flush >&$_ble_util_fd_stderr ble-edit/exec:gexec/invoke-hook-with-setexit POSTEXEC + local msg= if ((_ble_edit_exec_lastexit)); then # SIGERR処理 ble-edit/exec:gexec/invoke-hook-with-setexit ERR - if [[ $bleopt_exec_errexit_mark == $'\e[91m[ble: exit %d]\e[m' ]]; then - ble/util/print "${_ble_term_setaf[9]}[ble: exit $_ble_edit_exec_lastexit]$_ble_term_sgr0" - elif [[ $bleopt_exec_errexit_mark ]]; then + if [[ $bleopt_exec_errexit_mark ]]; then local ret ble/util/sprintf ret "$bleopt_exec_errexit_mark" "$_ble_edit_exec_lastexit" - x=0 y=0 g=0 ble/canvas/trace "$ret" - ble/util/print "$ret" - fi >&3 # Note: >&3 は set -x 対策による呼び出し元のリダイレクトと対応 #D0930 + msg=$ret + fi + fi + + if ble/exec/time#mark-enabled; then + local format=$bleopt_exec_elapsed_mark + if [[ $format ]]; then + # ata + local ata=$((_ble_exec_time_ata/1000)) + if ((ata<1000)); then + ata="${ata}ms" + elif ((ata<1000*1000)); then + ata="${ata::${#ata}-3}.${ata:${#ata}-3}s" + else + local min + ((ata/=1000,min=ata/60,ata%=60)) + ata="${min}m${ata}s" + fi + + # cpu + local cpu='--.-' + if ((_ble_exec_time_tot)); then + cpu=$(((_ble_exec_time_usr+_ble_exec_time_sys)*1000/_ble_exec_time_tot)) + cpu=$((cpu/10)).$((cpu%10)) + fi + + local ret + ble/util/sprintf ret "$format" "$ata" "$cpu" + msg=$msg$ret + ble/string#ltrim "$_ble_edit_exec_BASH_COMMAND" + msg="$msg $ret" + fi + fi + + if [[ $msg ]]; then + x=0 y=0 g=0 LINES=1 ble/canvas/trace "$msg" confine:truncate + ble/util/buffer.print "$ret" fi } function ble-edit/exec:gexec/.setup { @@ -5675,12 +5956,21 @@ function ble-edit/exec:gexec/.setup { buff[${#buff[@]}]=ble-edit/exec:gexec/.begin for cmd in "${_ble_edit_exec_lines[@]}"; do if [[ "$cmd" == *[^' ']* ]]; then - # Note: $_ble_edit_exec_lastarg は $_ を設定するためのものである。 - local prologue="ble-edit/exec:gexec/.prologue '${cmd//$q/$Q}' \"\$_ble_edit_exec_lastarg\"" - buff[${#buff[@]}]="builtin eval -- '${prologue//$q/$Q}" - buff[${#buff[@]}]="${cmd//$q/$Q}" - buff[${#buff[@]}]="{ ble-edit/exec:gexec/.save-last-arg; } &>/dev/null'" # Note: &>/dev/null は set -x 対策 #D0930 - buff[${#buff[@]}]="{ ble-edit/exec:gexec/.epilogue; } 3>&2 &>/dev/null" + # Note: restore-lastarg の $_ble_edit_exec_lastarg は $_ を設定するための + # ものである。 + # Note #D0465: restore-lastarg と実際のコマンドを同じ eval の中に入れるの + # は set -v の時の出力を抑える為である。prologue で set -v を復元した直 + # 後にそのままコマンドを実行しないと無駄な出力がされてしまう。 + # Note #D0465: 実際のコマンドと save-lastarg を同じ eval の中に入れている + # のは、同じ eval の中でないと $_ が失われてしまうから (特に eval を出 + # る時に eval の最終引数になってしまう)。 + local prologue="" + buff[${#buff[@]}]="ble-edit/exec:gexec/.prologue '${cmd//$q/$Q}'" + buff[${#buff[@]}]='{ time builtin eval -- "ble-edit/exec:gexec/.restore-lastarg \"\$_ble_edit_exec_lastarg\"' + buff[${#buff[@]}]='$_ble_edit_exec_BASH_COMMAND' + buff[${#buff[@]}]='{ ble-edit/exec:gexec/.save-lastarg; } &>/dev/null' # Note: &>/dev/null は set -x 対策 #D0930 + buff[${#buff[@]}]='" 2>&$_ble_util_fd_stderr; } 2>| "$_ble_exec_time_TIMEFILE"' + buff[${#buff[@]}]='{ ble-edit/exec:gexec/.epilogue; } 3>&2 &>/dev/null' ((count++)) # ※直接 $cmd と書き込むと文法的に破綻した物を入れた時に diff --git a/src/util.sh b/src/util.sh index dbbf5208..76bf9786 100644 --- a/src/util.sh +++ b/src/util.sh @@ -4749,9 +4749,12 @@ _ble_util_clock_reso= _ble_util_clock_type= function ble/util/clock/.initialize { local LC_ALL= LC_NUMERIC=C - if ((_ble_bash>=50000)) && [[ $EPOCHREALTIME == *.???* ]]; then + if ((_ble_bash>=50000)) && { + local now=$EPOCHREALTIME + [[ $now == *.???* && $now != $EPOCHREALTIME ]]; }; then # implementation with EPOCHREALTIME - _ble_util_clock_base=$((10#0${EPOCHREALTIME%.*})) + readonly EPOCHREALTIME + _ble_util_clock_base=$((10#0${now%.*})) _ble_util_clock_reso=1 _ble_util_clock_type=EPOCHREALTIME function ble/util/clock { @@ -4788,6 +4791,7 @@ function ble/util/clock/.initialize { ((ret=(now-_ble_util_clock_base)*1000)) } elif [[ $SECONDS && ! ${SECONDS//[0-9]} ]]; then + readonly SECONDS _ble_util_clock_base=$SECONDS _ble_util_clock_reso=1000 _ble_util_clock_type=SECONDS