[MSYS2]: Suggestions sometimes don't appear at all #133

rashil2000 · 2021-08-28T17:07:31Z

ble version: 0.4.0-devel3+92c7b26
Bash version: 5.1.8(1)-release (x86_64-pc-msys)

Hi!

I saw in your comment that MSYS2 support was recently added, so I wanted to report this here.

The issue is that the auto-suggestions are very slow to appear, and sometimes they don't appear at all. I'm on a laptop, so power consumption might be interfering with how snappy the input is. Therefore I've tried to record on both battery-mode and plugged-in mode.

battery

plugged-in

I have noticed that the issue worsens as more and more different applications are open on my laptop.

Is this something that can be rectified?

akinomyoga · 2021-08-28T23:57:18Z

There is an option bleopt complete_timeout_auto for the timeout of auto-complete, whose default value is 5000 millisecond. It is the option to prevent Bash processes from occupying the CPU for unresponsive auto-complete. When you turn the option off, are the suggestions shown (even though it might be after some long time)?

# blerc

bleopt complete_timeout_auto=

rashil2000 · 2021-08-29T09:46:46Z

Disabling timeout does make them appear, eventually.

akinomyoga · 2021-08-29T10:37:17Z

OK, so the behavior that auto-complete sometimes doesn't show anything is the feature of ble.sh. You can add the setting in your blerc to disable the timeout or to make the timeout longer.

For the issue that it takes longer time in the battery mode, it is basically the same as I have described in #96 (comment): I try to improve the situation if we can identify the bottleneck, but I cannot ensure that we can solve the problem in slow systems. You have mentioned that your computer is not slow, but that's not my point. I should have written slow systems but not slow computers. No matter how fast your hardware is, some systems---such as WSL2, MSYS2, Cygwin, and Termux---that emulate the Unix behavior on top of different kernel/systems can be slow.

If you still think the slow response in MSYS2 in the battery mode is an issue, could you test the same commands in Q1--Q4 in #96 (comment) and #96 (comment)?

rashil2000 · 2021-08-30T05:22:03Z

Thanks for the info. I completely understand that MSYS2/Cygwin/Termux can be slow since they're essentially emulating stuff.

I ran the commands you mentioned, here are the results:

Q1: What are the results of the following command in the battery mode and the plugged-in mode?

18854.195 usec/eval: ble/util/msleep 10 (x20) # battery
18035.410 usec/eval: ble/util/msleep 10 (x10) # plugged-in

Q2: When you turn off auto-complete and other background processing, does the response in the battery mode change?

Won't this turn off the suggestions entirely?

Q3: With the following settings In addition to the above settings, does the response in the battery mode change?

Slight improvement (note that I didn't run the 3 commands in Q3 as they would turned the suggestions off).

Q4: What are the result of the following command in the battery and plugged-in modes respectively.

5359.880 usec/eval: ble/util/assign a "echo $((b++))" (x20) # battery
4099.710 usec/eval: ble/util/assign a "echo $((b++))" (x50) # plugged-in

akinomyoga · 2021-08-31T00:14:55Z

Thank you!

Won't this turn off the suggestions entirely?

Oh, you are right. I was forgetting that we want to test the performance of auto-complete in this PR.

In these answers, I see there seems to be no bottleneck in the synchronization of background processing and access to the temporary files. I'm not sure how much is the slight improvement in your answer to Q3, but I assume that the highlighting of filenames and variables are not the major factor of the current performance degradation in the battery mode.

I have again looked at the animated GIF you provided and noticed that it seems to take time for the auto-complete based on the command history. This might be related to the history size.

Q5: What are the results of the following commands:

$ builtin history | wc
$ wc ~/.bash_history # your history file

Q6: Is the response for auto-complete of the filenames (which is not in the command history) also slow in the battery mode?

rashil2000 · 2021-08-31T06:25:01Z

Q5: What are the results of the following commands:

745    3043   23839
746  2302 18662

Q6: Is the response for auto-complete of the filenames (which is not in the command history) also slow in the battery mode?

Yes, I don't notice any difference

akinomyoga · 2021-08-31T06:30:55Z

Thanks. Hmm, OK. So the history is small, and the delay is not specific to the history auto-complete.

Q7: What about the results of the following command in the battery and plugged-in modes?

$ ble-measure -a 50 'ble/util/is-stdin-ready'

rashil2000 · 2021-08-31T06:48:38Z

266.655 usec/eval: ble/util/is-stdin-ready (x500)  # battery
172.557 usec/eval: ble/util/is-stdin-ready (x1000) # plugged-in

akinomyoga · 2021-08-31T06:54:09Z

OK, this seems to be within the acceptable range. I currently don't have an idea on the other possibility. I will later try to reproduce the problem after I go back home.

Q8: May I ask which terminal do you use? Is there any other advice on reproducing your setup?

rashil2000 · 2021-08-31T07:10:25Z

I use (and love) the Windows Terminal Preview :)

But these issues can be reproduced on conhost and mintty too.

My .bashrc is here https://github.com/rashil2000/dotfiles/blob/master/bash/.bashrc

The MSYS2 kernel version is visible in the GIFs and the bash version is there in the top comment in this thread.

Thank you so much for your time so far!

akinomyoga · 2021-08-31T23:37:23Z

My bad, it was just a bug of task scheduling that can affect the general environment not specific to MSYS2. I added a fix fea5f5b. Could you check the latest commit by ble-update to see if it is improved?

ble.sh uses some clocks for the task scheduling of the background processing. Actually, two different clocks are internally used in the task scheduling, and the times of the two clocks should not be mixed. But, in the scheduling of auto-complete, I have been measuring the time using one clock and scheduled the next processing based on the other clock, which caused the problem. I haven't observed the problem so far in the other environments probably because the inconsistency of two clocks happens rarely, and the problem arises in a race condition.

rashil2000 · 2021-09-01T11:07:45Z

Yes! That solved the issue!

The suggestions appear almost instantly now.

Thank you!!

Should I close this?

akinomyoga · 2021-09-01T11:22:49Z

Nice! Thank you for checking that the issue has been solved. Then, you can now close the issue. Thank you again for reporting the issue and answering a number of questions!

rashil2000 · 2021-09-01T18:24:12Z

Thank you and welcome 😊

On an unrelated note, may I ask why, after the ble-attach statement, output of any echo commands in the .bashrc doesn't appear?

akinomyoga · 2021-09-01T20:49:21Z

On an unrelated note, may I ask why, after the ble-attach statement, output of any echo commands in the .bashrc doesn't appear?

To suppress the output from GNU Readline, ble.sh redirects standard streams to temporary files. The end of bashrc is the last place that we can redirect the standard streams for Readline, which is the reason that ble-attach needs to be placed at the bottom of bashrc.

Do you think there is some situation that one cannot put ble-attach at the end of bashrc and this causes problems? Maybe we can redirect only the standard error output for Readline, and the standard output may be kept connected to TTY. At least in Linux and Cygwin, it seems that Readline doesn't output anything to stdout. I need to check for the other environments and other versions of Bash.

Edit: If you want to check the redirected output, you may run the following command:

$ cat "$_ble_base_run/$$.stdout"

rashil2000 · 2021-09-02T08:29:47Z

Do you think there is some situation that one cannot put ble-attach at the end of .bashrc and this causes problems?

I haven't come across any problems yet. I'm fine with putting it at the bottom :)

I just got to know about this behavior because I was trying to run a little experiment. PowerShell has this really neat feature of displaying how much time it took to initialize and load the shell. I tried to replicate the functionality in bash and zsh (in MSYS2), by putting the following line at the top of the very first initialization file (/etc/profile for bash and /etc/zsh/zshenv for zsh):

__shell_start=`/usr/bin/date +%s%3N`

and the following line at the end of last files (.bashrc and .zshrc):

echo -e "\nLoading personal and system profiles took $(($(date +%s%3N) - __shell_start))ms."

Here are the timings (in seconds):

plugged-in

pwsh - 1.5
zsh - 1
bash (without ble.sh) - 2
bash (with ble.sh) - 4.3

battery

pwsh - 4
zsh - 3
bash (without ble.sh) - 5
bash (with ble.sh) - 10.5

(ble.sh seems to add significant overhead to loading time - 2.3 seconds in plugged-in mode and 5.5 seconds in battery mode - but I didn't report this because I think this is due to the MSYS2 emulation as you mentioned - please correct me if I'm wrong 😅)

akinomyoga · 2021-09-17T10:14:46Z

On an unrelated note, may I ask why, after the ble-attach statement, output of any echo commands in the .bashrc doesn't appear?

[...] Maybe we can redirect only the standard error output for Readline, and the standard output may be kept connected to TTY. At least in Linux and Cygwin, it seems that Readline doesn't output anything to stdout. I need to check for the other environments and other versions of Bash.

FYI, I implemented the above idea (only redirecting the standard error) in commit a30887f, and tested it with different systems. Now the standard output in .bashrc is visible in the terminal after ble-attach. The standard error is still subject to the redirection so invisible after ble-attach, but that's the restriction of ble.sh.

akinomyoga · 2021-09-17T10:37:10Z

Here are the timings (in seconds):

plugged-in

pwsh - 1.5

zsh - 1

bash (without ble.sh) - 2

bash (with ble.sh) - 4.3

battery

pwsh - 4

zsh - 3

bash (without ble.sh) - 5

bash (with ble.sh) - 10.5

(ble.sh seems to add significant overhead to loading time - 2.3 seconds in plugged-in mode and 5.5 seconds in battery mode - but I didn't report this because I think this is due to the MSYS2 emulation as you mentioned - please correct me if I'm wrong 😅)

Sorry for the late reply. Actually, after I saw your comment, I have tested the initialization time in my environment and found that the overhead is about one second there. The bottleneck seems to be the cost of fork & exec in the initialization. I wanted to investigate in more details but was busy, so my reply has been delayed. If you are still interested in the delay, you may check the fork speed of your system by the following command:

$ while :; do date; done | uniq -c

You can terminate the command by pressing C-c several times. The below are the results in my systems. The numbers represent the number of forks and execs per second. I'm usually using Linux and Cygwin and the delay is negligible in these systems, but MSYS2 is three times slower than Cygwin so it is possible that it makes the delay significant enough.

# GNU/Linux
   1911 Fri Sep 17 19:20:38 JST 2021
   1827 Fri Sep 17 19:20:39 JST 2021
   1753 Fri Sep 17 19:20:40 JST 2021
   1629 Fri Sep 17 19:20:41 JST 2021
   1619 Fri Sep 17 19:20:42 JST 2021

# Cygwin
     38 Fri Sep 17 19:21:05     2021
     37 Fri Sep 17 19:21:06     2021
     38 Fri Sep 17 19:21:07     2021
     39 Fri Sep 17 19:21:08     2021
     38 Fri Sep 17 19:21:09     2021

# MSYS2
     13 Fri Sep 17 19:22:23 JST 2021
     14 Fri Sep 17 19:22:24 JST 2021
     12 Fri Sep 17 19:22:25 JST 2021
     13 Fri Sep 17 19:22:26 JST 2021
     13 Fri Sep 17 19:22:27 JST 2021

You may also output the initialization benchmarks (until ble-attach) by modifying the beginning of ble.pp as follows and regenerate ble.sh:

diff --git a/ble.pp b/ble.pp
index 27989c2..dbc43a1 100644
--- a/ble.pp
+++ b/ble.pp
@@ -1,7 +1,7 @@
 #!/bin/bash
 #%$> out/ble.sh
 #%[release = 0]
-#%[measure_load_time = 0]
+#%[measure_load_time = 1]
 #%[debug_keylogger = 1]
 #%#----------------------------------------------------------------------------
 #%if measure_load_time

The example output in my environment is something like this. Normally, ble.sh seems to perform 9 forks in initialization in MSYS2, which may lead to the overhead observed in MSYS2.

$ bash
ble.sh: 1631874833.334162 load start
ble.sh: 1631874833.406806 parsed
[Elapsed 0.345s; CPU U:0.030s S:0.183s (61.73%)] ble.pp/prologue (6 forks)
[Elapsed 0.023s; CPU U:0.000s S:0.015s (65.46%)] src/def.sh (0 forks)
[Elapsed 0.321s; CPU U:0.108s S:0.107s (66.93%)] src/util.sh (3 forks)
[Elapsed 0.073s; CPU U:0.047s S:0.031s (107.04%)] src/decode.sh (0 forks)
[Elapsed 0.038s; CPU U:0.016s S:0.015s (82.16%)] src/color.sh (0 forks)
[Elapsed 0.062s; CPU U:0.016s S:0.030s (73.74%)] src/canvas.sh (0 forks)
[Elapsed 0.035s; CPU U:0.030s S:0.000s (86.09%)] src/history.sh (0 forks)
[Elapsed 0.063s; CPU U:0.047s S:0.015s (99.18%)] src/edit.sh (0 forks)
[Elapsed 0.033s; CPU U:0.016s S:0.015s (95.02%)] lib/core-syntax-def.sh (0 forks)
[Elapsed 0.045s; CPU U:0.031s S:0.015s (102.73%)] lib/core-complete-def.sh (0 forks)
[Elapsed 0.032s; CPU U:0.000s S:0.031s (95.79%)] ble.pp/epilogue (0 forks)
[Elapsed 0.030s; CPU U:0.000s S:0.031s (103.33%)] blerc: '/home/murase/.blerc' (0 forks)
[Elapsed 1.326s; CPU U:0.434s S:0.581s (76.55%)] Total
ble.sh: 1631874834.749080 load end
ble.sh: 1631874835.033422 start prompt-attach
ble.sh: 1631874835.038156 end prompt-attach

If that is the case, I can look for whether it is possible to reduce the number of forks in the MSYS2 system.

rashil2000 · 2021-09-17T15:24:38Z

I ran the benchmarks under various scenarios, here are the results:

Cygwin

Battery

Vanilla bash

Ble.sh

Load time

Plugged

Vanilla bash

Ble.sh

Load time

MSYS2

Battery

Vanilla bash

Ble.sh

Load time

Plugged

Vanilla bash

Ble.sh

Load time

rashil2000 · 2021-09-17T16:33:59Z

It looks like the presence of ble.sh decreases how many fork calls can be done in a second (also confirmed in WSL2).

akinomyoga · 2021-09-17T16:42:50Z

Thank you! These results are interesting. In your system, there are essentially no differences in speed between Cygwin and MSYS2. Also, it seems that the load time is only a small part of the total overhead of using ble.sh: 0.75 / 2.3s (plugged) and 2.05 / 5.5s. (battery) The fork doesn't seem to be the major cause of the delay in your system.

It looks like the presence of ble.sh decreases how many fork calls can be done in a second (also confirmed in WSL2).

This is also observed in Linux. Actually, the footprint (i.e., the memory usage of the process) will directly affect the fork performance. For example, even a single large array affects the speed as follows:

# In my Linux, bash-5.0.11 without ble.sh

$ while :; do date; done | uniq -c
    810 Sat Sep 18 01:39:19 JST 2021
   2201 Sat Sep 18 01:39:20 JST 2021
   2086 Sat Sep 18 01:39:21 JST 2021
   1849 Sat Sep 18 01:39:22 JST 2021
   1718 Sat Sep 18 01:39:23 JST 2021
   1648 Sat Sep 18 01:39:24 JST 2021
   1587 Sat Sep 18 01:39:25 JST 2021
   1558 Sat Sep 18 01:39:26 JST 2021
   1406 Sat Sep 18 01:39:27 JST 2021
^C
$ A=({000000..999999})     # <-- create a large array
$ while :; do date; done | uniq -c
     96 Sat Sep 18 01:39:41 JST 2021
    194 Sat Sep 18 01:39:42 JST 2021
    186 Sat Sep 18 01:39:43 JST 2021
    188 Sat Sep 18 01:39:44 JST 2021
    173 Sat Sep 18 01:39:45 JST 2021
    173 Sat Sep 18 01:39:46 JST 2021
    169 Sat Sep 18 01:39:47 JST 2021
    182 Sat Sep 18 01:39:48 JST 2021
    176 Sat Sep 18 01:39:49 JST 2021

rashil2000 · 2021-09-17T16:56:03Z

Actually, the footprint (i.e., the memory usage of the process) will directly affect the fork performance. For example, even a single large array affects the speed as follows:

# In my Linux, bash-5.0.11 without ble.sh

$ while :; do date; done | uniq -c
    810 Sat Sep 18 01:39:19 JST 2021
   2201 Sat Sep 18 01:39:20 JST 2021
   2086 Sat Sep 18 01:39:21 JST 2021
   1849 Sat Sep 18 01:39:22 JST 2021
   1718 Sat Sep 18 01:39:23 JST 2021
   1648 Sat Sep 18 01:39:24 JST 2021
   1587 Sat Sep 18 01:39:25 JST 2021
   1558 Sat Sep 18 01:39:26 JST 2021
   1406 Sat Sep 18 01:39:27 JST 2021
^C
$ A=({000000..999999})     # <-- create a large array
$ while :; do date; done | uniq -c
     96 Sat Sep 18 01:39:41 JST 2021
    194 Sat Sep 18 01:39:42 JST 2021
    186 Sat Sep 18 01:39:43 JST 2021
    188 Sat Sep 18 01:39:44 JST 2021
    173 Sat Sep 18 01:39:45 JST 2021
    173 Sat Sep 18 01:39:46 JST 2021
    169 Sat Sep 18 01:39:47 JST 2021
    182 Sat Sep 18 01:39:48 JST 2021
    176 Sat Sep 18 01:39:49 JST 2021

Oh, that's a very interesting note. Is there any way to benchmark memory usage then (similar to how you did for CPU time)?

akinomyoga · 2021-09-17T17:25:40Z

Oh, that's a very interesting note. Is there any way to benchmark memory usage then (similar to how you did for CPU time)?

Oh, I had never thought of measuring memory usage, but it should be possible with top, ps or some other tools. I searched and found that /proc/<PID>/status also includes the information of memory usage. For example, we can extract the real memory size of the shell by

$ grep RSS /proc/$$/status
VmRSS:     10240 kB

This is the summary for my systems.

System	without ble.sh	with ble.sh	history size
Linux	7384 kB	89584 kB	34490
Cygwin	10240 kB	41088 kB	8063
MSYS2	9472 kB	30848 kB	502

With ble.sh, the footprint of the Bash process will significantly increase. I actually recognize this problem, which is one of the problems that are hard to solve. Some part of this large memory use can be explained by the command history managed by shell arrays created by ble.sh. In the fourth column (history size), I added the number of command history entries which can be checked by history 1.

rashil2000 · 2021-09-17T20:17:43Z

System	vanilla	ble.sh	history size
MSYS2	11072 kB	31040 kB	1176
Cygwin	11136 kB	30976 kB	1176

(both Cygwin and MSYS2 share the same Home folder so history is same)

akinomyoga added the bug label Sep 1, 2021

rashil2000 closed this as completed Sep 1, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[MSYS2]: Suggestions sometimes don't appear at all #133

[MSYS2]: Suggestions sometimes don't appear at all #133

rashil2000 commented Aug 28, 2021

akinomyoga commented Aug 28, 2021 •

edited

Loading

rashil2000 commented Aug 29, 2021

akinomyoga commented Aug 29, 2021 •

edited

Loading

rashil2000 commented Aug 30, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Aug 31, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Aug 31, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Aug 31, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Sep 1, 2021

akinomyoga commented Sep 1, 2021

rashil2000 commented Sep 1, 2021

akinomyoga commented Sep 1, 2021 •

edited

Loading

rashil2000 commented Sep 2, 2021 •

edited

Loading

akinomyoga commented Sep 17, 2021

akinomyoga commented Sep 17, 2021

rashil2000 commented Sep 17, 2021 •

edited

Loading

rashil2000 commented Sep 17, 2021 •

edited

Loading

akinomyoga commented Sep 17, 2021 •

edited

Loading

rashil2000 commented Sep 17, 2021

akinomyoga commented Sep 17, 2021

rashil2000 commented Sep 17, 2021

[MSYS2]: Suggestions sometimes don't appear at all #133

[MSYS2]: Suggestions sometimes don't appear at all #133

Comments

rashil2000 commented Aug 28, 2021

akinomyoga commented Aug 28, 2021 • edited Loading

rashil2000 commented Aug 29, 2021

akinomyoga commented Aug 29, 2021 • edited Loading

rashil2000 commented Aug 30, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Aug 31, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Aug 31, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Aug 31, 2021

akinomyoga commented Aug 31, 2021

rashil2000 commented Sep 1, 2021

akinomyoga commented Sep 1, 2021

rashil2000 commented Sep 1, 2021

akinomyoga commented Sep 1, 2021 • edited Loading

rashil2000 commented Sep 2, 2021 • edited Loading

akinomyoga commented Sep 17, 2021

akinomyoga commented Sep 17, 2021

rashil2000 commented Sep 17, 2021 • edited Loading

Cygwin

Battery

Vanilla bash

Ble.sh

Load time

Plugged

Vanilla bash

Ble.sh

Load time

MSYS2

Battery

Vanilla bash

Ble.sh

Load time

Plugged

Vanilla bash

Ble.sh

Load time

rashil2000 commented Sep 17, 2021 • edited Loading

akinomyoga commented Sep 17, 2021 • edited Loading

rashil2000 commented Sep 17, 2021

akinomyoga commented Sep 17, 2021

rashil2000 commented Sep 17, 2021

akinomyoga commented Aug 28, 2021 •

edited

Loading

akinomyoga commented Aug 29, 2021 •

edited

Loading

akinomyoga commented Sep 1, 2021 •

edited

Loading

rashil2000 commented Sep 2, 2021 •

edited

Loading

rashil2000 commented Sep 17, 2021 •

edited

Loading

rashil2000 commented Sep 17, 2021 •

edited

Loading

akinomyoga commented Sep 17, 2021 •

edited

Loading