Bash runs my vim slower than Cygwin's vim

Bash runs my vim slower than Cygwin's vim

[Gary Johnson]

I build my own copy of Vim for the Cygwin terminal from the source
at https://github.com/vim/vim.git.  Lately, I've noticed the startup
time getting slower, so I investigated.  One of the things
I discovered was this difference between the run times of the
official Cygwin vim package and the vim I built myself.  Both are
version 8.2.4372 and built using the same configuration and compiler
flags except for some options such as Ruby that I don't have support
for on my system.

    $ time /usr/bin/vim -N -u NONE -i NONE -cq

    real    0m0.119s
    user    0m0.062s
    sys     0m0.015s

    $ time /usr/local/src/vim-debug/vim/src/vim -N -u NONE -i NONE -cq

    real    0m1.422s
    user    0m0.015s
    sys     0m0.093s

I ran the same commands using strace and found the cumulative times
to be the same within a few milliseconds (about 320 ms).

Since the difference didn't appear to be in Vim itself, I thought
the difference might be in bash, so I ran both programs using strace
like this.

    $ strace -o strace_bash_cygwin_vim bash -c "/usr/bin/vim -N -u NONE -i NONE -cq"
    $ strace -o strace_bash_local_vim bash -c "/usr/local/src/vim-debug/vim/src/vim -N -u NONE -i NONE -cq"

Those traces show a significant difference in the times bash takes
to perform these three operations on those two vim executables.

1.  [main] bash {PID} child_info_spawn::worker: priority class 32

    Cygwin's vim:    261 us
    My vim:       247217 us

2.  [main] bash {PID} child_info_spawn::worker: pid {PID}, prog_arg {program}, cmd line (null))

    Cygwin's vim:   4515 us
    My vim:       709705 us

3.  [main] bash {PID}! child_info::sync: pid {PID}, WFMO returned 0, exit_code 0x103, res 1

    Cygwin's vim:  16156 us
    My vim:       575127 us

Those operations are shown as they appear in the strace outputs with
some context below.


strace_bash_cygwin_vim
----------------------

  104  240566 [main] bash 9075 spawnve: spawnve (/usr/bin/vim, /usr/bin/vim, 0x80005A9D0)
   94  240660 [main] bash 9075 child_info_spawn::worker: mode = 3, prog_arg = /usr/bin/vim
   51  240711 [main] bash 9075 perhaps_suffix: prog '/usr/bin/vim'
   63  240774 [main] bash 9075 normalize_posix_path: src /usr/bin/vim
   64  240838 [main] bash 9075 normalize_posix_path: /usr/bin/vim = normalize_posix_path (/usr/bin/vim)
   52  240890 [main] bash 9075 mount_info::conv_to_win32_path: conv_to_win32_path (/usr/bin/vim)
   49  240939 [main] bash 9075 mount_info::conv_to_win32_path: src_path /usr/bin/vim, dst C:\cygwin64\bin\vim, flags 0x20008, rc 0
  132  241071 [main] bash 9075 symlink_info::check: 0xC0000034 = NtCreateFile (\??\C:\cygwin64\bin\vim)
   49  241120 [main] bash 9075 symlink_info::check: 0xC0000034 = NtQueryInformationFile (\??\C:\cygwin64\bin\vim)
  135  241255 [main] bash 9075 symlink_info::check: 0x0 = NtCreateFile (\??\C:\cygwin64\bin\vim.exe)
  201  241456 [main] bash 9075 symlink_info::check: not a symlink
   74  241530 [main] bash 9075 symlink_info::check: 0 = symlink.check(C:\cygwin64\bin\vim.exe, 0xFFFFA410) (mount_flags 0x20008, path_flags 0x0)
   48  241578 [main] bash 9075 path_conv::check: this->path(C:\cygwin64\bin\vim.exe), has_acls(1)
   68  241646 [main] bash 9075 perhaps_suffix: buf C:\cygwin64\bin\vim.exe, suffix found '.exe'
  261  241907 [main] bash 9075 child_info_spawn::worker: priority class 32
  138  242045 [main] bash 9075 fhandler_console::need_invisible: invisible_console 0
   99  242144 [main] bash 9075 build_env: envp 0x80005A9D0

...

  158  243852 [main] bash 9075 child_info::child_info: subproc_ready 0x228
 4515  248367 [main] bash 9075 child_info_spawn::worker: pid 9075, prog_arg /usr/bin/vim, cmd line (null))
   92  248459 [main] bash 9075! child_info_spawn::worker: new process name \\?\C:\cygwin64\bin\vim.exe
   98  248557 [main] bash 9075! child_info_spawn::worker: spawned windows pid 36936
   58  248615 [main] bash 9075! child_info::sync: n 2, waiting for subproc_ready(0x228) and child process(0x274)
--- Process 36936 created

...

   87    6496 [main] vim 9075 child_info::ready: signalled 0x228 that I was ready
16156  264771 [main] bash 9075! child_info::sync: pid 36936, WFMO returned 0, exit_code 0x103, res 1
   77  264848 [main] bash 9075! fhandler_base::close_with_arch: line 1181:  /dev/cons0<0x18035A7C0> usecount + -1 = 3


strace_bash_local_vim
---------------------

   96  235661 [main] bash 9090 spawnve: spawnve (/usr/local/src/vim-debug/vim/src/vim, /usr/local/src/vim-debug/vim/src/vim, 0x80005A9F0)
   69  235730 [main] bash 9090 child_info_spawn::worker: mode = 3, prog_arg = /usr/local/src/vim-debug/vim/src/vim
   59  235789 [main] bash 9090 perhaps_suffix: prog '/usr/local/src/vim-debug/vim/src/vim'
   57  235846 [main] bash 9090 normalize_posix_path: src /usr/local/src/vim-debug/vim/src/vim
   71  235917 [main] bash 9090 normalize_posix_path: /usr/local/src/vim-debug/vim/src/vim = normalize_posix_path (/usr/local/src/vim-debug/vim/src/vim)
   49  235966 [main] bash 9090 mount_info::conv_to_win32_path: conv_to_win32_path (/usr/local/src/vim-debug/vim/src/vim)
   61  236027 [main] bash 9090 mount_info::conv_to_win32_path: src_path /usr/local/src/vim-debug/vim/src/vim, dst C:\cygwin64\usr\local\src\vim-debug\vim\src\vim, flags 0x30008, rc 0
  140  236167 [main] bash 9090 symlink_info::check: 0xC0000034 = NtCreateFile (\??\C:\cygwin64\usr\local\src\vim-debug\vim\src\vim)
   63  236230 [main] bash 9090 symlink_info::check: 0xC0000034 = NtQueryInformationFile (\??\C:\cygwin64\usr\local\src\vim-debug\vim\src\vim)
  133  236363 [main] bash 9090 symlink_info::check: 0x0 = NtCreateFile (\??\C:\cygwin64\usr\local\src\vim-debug\vim\src\vim.exe)
  237  236600 [main] bash 9090 symlink_info::check: not a symlink
   95  236695 [main] bash 9090 symlink_info::check: 0 = symlink.check(C:\cygwin64\usr\local\src\vim-debug\vim\src\vim.exe, 0xFFFFA3F0) (mount_flags 0x30008, path_flags 0x0)
   47  236742 [main] bash 9090 path_conv::check: this->path(C:\cygwin64\usr\local\src\vim-debug\vim\src\vim.exe), has_acls(1)
   59  236801 [main] bash 9090 perhaps_suffix: buf C:\cygwin64\usr\local\src\vim-debug\vim\src\vim.exe, suffix found '.exe'
247217  484018 [main] bash 9090 child_info_spawn::worker: priority class 32
  254  484272 [main] bash 9090 fhandler_console::need_invisible: invisible_console 0
   78  484350 [main] bash 9090 build_env: envp 0x80005A9F0

...

   84  486764 [main] bash 9090 child_info::child_info: subproc_ready 0x338
709705 1196469 [main] bash 9090 child_info_spawn::worker: pid 9090, prog_arg /usr/local/src/vim-debug/vim/src/vim, cmd line (null))
  153 1196622 [main] bash 9090! child_info_spawn::worker: new process name \\?\C:\cygwin64\usr\local\src\vim-debug\vim\src\vim.exe
  160 1196782 [main] bash 9090! child_info_spawn::worker: spawned windows pid 37316
   85 1196867 [main] bash 9090! child_info::sync: n 2, waiting for subproc_ready(0x338) and child process(0x3AC)
--- Process 37316 created

...

  161    6615 [main] vim 9090 open_shared: name (null), n 0, shared 0x180000000 (wanted 0x180000000), h 0x20C, *m 6
  130    6745 [main] vim 9090 child_info::ready: signalled 0x338 that I was ready
575127 1771994 [main] bash 9090! child_info::sync: pid 37316, WFMO returned 0, exit_code 0x103, res 1
   94 1772088 [main] bash 9090! fhandler_base::close_with_arch: line 1181:  /dev/cons0<0x18035A7C0> usecount + -1 = 3


My vim version
--------------

VIM - Vi IMproved 8.2 (2019 Dec 12, compiled Mar 10 2022 13:42:57)
Included patches: 1-4372
Compiled by user@hostname
Huge version without GUI.  Features included (+) or not (-):
+acl               +file_in_path      +mouse_urxvt       -tag_any_white
+arabic            +find_in_path      +mouse_xterm       -tcl
+autocmd           +float             +multi_byte        +termguicolors
+autochdir         +folding           +multi_lang        +terminal
-autoservername    -footer            -mzscheme          +terminfo
-balloon_eval      +fork()            +netbeans_intg     +termresponse
+balloon_eval_term +gettext           +num64             +textobjects
-browse            -hangul_input      +packages          +textprop
++builtin_terms    +iconv             +path_extra        +timers
+byte_offset       +insert_expand     +perl/dyn          +title
+channel           +ipv6              +persistent_undo   -toolbar
+cindent           +job               +popupwin          +user_commands
-clientserver      +jumplist          +postscript        +vartabs
+clipboard         +keymap            +printer           +vertsplit
+cmdline_compl     +lambda            +profile           +vim9script
+cmdline_hist      +langmap           -python            +viminfo
+cmdline_info      +libcall           -python3           +virtualedit
+comments          +linebreak         +quickfix          +visual
+conceal           +lispindent        +reltime           +visualextra
+cryptv            +listcmds          +rightleft         +vreplace
+cscope            +localmap          -ruby              +wildignore
+cursorbind        -lua               +scrollbind        +wildmenu
+cursorshape       +menu              +signs             +windows
+dialog_con        +mksession         +smartindent       +writebackup
+diff              +modify_fname      -sodium            -X11
+digraphs          +mouse             -sound             -xfontset
-dnd               -mouseshape        +spell             -xim
-ebcdic            +mouse_dec         +startuptime       -xpm
+emacs_tags        -mouse_gpm         +statusline        -xsmp
+eval              -mouse_jsbterm     -sun_workshop      -xterm_clipboard
+ex_extra          +mouse_netterm     +syntax            -xterm_save
+extra_search      +mouse_sgr         +tag_binary
-farsi             -mouse_sysmouse    -tag_old_static
   system vimrc file: "$VIM/vimrc"
     user vimrc file: "$HOME/.vimrc"
 2nd user vimrc file: "~/.vim/vimrc"
      user exrc file: "$HOME/.exrc"
       defaults file: "$VIMRUNTIME/defaults.vim"
  fall-back for $VIM: "/usr/local/share/vim"
Compilation: gcc -c -I. -Iproto -DHAVE_CONFIG_H -ggdb -O2 -fstack-protector-strong -D_REENTRANT -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=1
Linking: gcc -L/usr/local/lib -Wl,--as-needed -o vim.exe -lm -lncursesw -liconv -lacl -lintl -Wl,--enable-auto-import -Wl,--export-all-symbols -Wl,--enable-auto-image-base -fstack-protector-strong -L/usr/lib/perl5/5.32/x86_64-cygwin-threads/CORE -lperl -lpthread -ldl -lcrypt


So, does anyone know why is takes so much longer for bash to run the
vim I built than the official Cygwin vim?  More importantly, how do
I fix this?

Waiting 1.4 seconds for vim to start isn't too bad, but when
I actually edit a file with my normal configuration, it takes
5 seconds for vim to start vs. 1.2 seconds for Cygwin's vim.

Cygwin and all my Cygwin programs are up-to-date.  I'm running
Windows 10 Enterprise version 1909.

Regards,
Gary

Re: Bash runs my vim slower than Cygwin's vim

[Adam Dinwoodie]

On Thu, Mar 10, 2022 at 04:55:40PM -0800, Gary Johnson wrote:
> I build my own copy of Vim for the Cygwin terminal from the source
> at https://github.com/vim/vim.git.  Lately, I've noticed the startup
> time getting slower, so I investigated.  One of the things
> I discovered was this difference between the run times of the
> official Cygwin vim package and the vim I built myself.  Both are
> version 8.2.4372 and built using the same configuration and compiler
> flags except for some options such as Ruby that I don't have support
> for on my system.
> 
> <snip>
> 
> So, does anyone know why is takes so much longer for bash to run the
> vim I built than the official Cygwin vim?  More importantly, how do
> I fix this?

There are a few differences that jump to mind between the Cygwin
packaged Vim and your locally built Vim.  This isn't my area of
expertise by a long shot, but my guess would be it's one of these:

- Cygwin packages built using Cygport and packaged for release will have
  the binaries stripped, removing debug symbols and the like and
  separating them into a different -debug package.  That means that the
  binaries that are loaded for day-to-day use are smaller, and may well
  mean they're faster too.

- Binaries installed by Cygwin setup will get automatically added to
  Cygwin's rebase database.  I don't think that would help here --
  problems with rebase normally manifest as fork failures, not just
  slowness -- but it's another difference that seemed like it might be
  relevant.

- Cygwin's Vim has a handful of patches.  I've just had a quick look and
  none of them seem obviously likely to make a significant perf
  difference to me, but it was only a quick look and see above re lack
  of expertise :)

I suspect the best way to investigate this further will be to try to
narrow down the possible differences between your build and the official
Cygwin build.  To do that, I'd probably start with getting the source
for the official Cygwin build, compiling it using Cygport (`cygport
vim.cygport prep compile install package`), then "installing" it as if
it were a regular Cygwin package (`tar -xaf vim-*/dist/vim/vim-*.tar.*
-C /` is close enough for most purposes).

HTH

Adam

Re: Bash runs my vim slower than Cygwin's vim

[Gary Johnson]

On 2022-03-11, Adam Dinwoodie wrote:
> On Thu, Mar 10, 2022 at 04:55:40PM -0800, Gary Johnson wrote:
> > I build my own copy of Vim for the Cygwin terminal from the source
> > at https://github.com/vim/vim.git.  Lately, I've noticed the startup
> > time getting slower, so I investigated.  One of the things
> > I discovered was this difference between the run times of the
> > official Cygwin vim package and the vim I built myself.  Both are
> > version 8.2.4372 and built using the same configuration and compiler
> > flags except for some options such as Ruby that I don't have support
> > for on my system.
> > 
> > <snip>
> > 
> > So, does anyone know why is takes so much longer for bash to run the
> > vim I built than the official Cygwin vim?  More importantly, how do
> > I fix this?
> 
> There are a few differences that jump to mind between the Cygwin
> packaged Vim and your locally built Vim.  This isn't my area of
> expertise by a long shot, but my guess would be it's one of these:

Thanks for taking a look.

> - Cygwin packages built using Cygport and packaged for release will have
>   the binaries stripped, removing debug symbols and the like and
>   separating them into a different -debug package.  That means that the
>   binaries that are loaded for day-to-day use are smaller, and may well
>   mean they're faster too.

The Cygwin vim was built with -ggdb, but I didn't look for strip and
Cygwin's file doesn't report whether or not binaries are stripped--
it probably can't determine that.  I'll try stripping mine.

> - Binaries installed by Cygwin setup will get automatically added to
>   Cygwin's rebase database.  I don't think that would help here --
>   problems with rebase normally manifest as fork failures, not just
>   slowness -- but it's another difference that seemed like it might be
>   relevant.
> 
> - Cygwin's Vim has a handful of patches.  I've just had a quick look and
>   none of them seem obviously likely to make a significant perf
>   difference to me, but it was only a quick look and see above re lack
>   of expertise :)

I looked at those, too, and didn't see anything that I thought would
cause a performance issue, either.

> I suspect the best way to investigate this further will be to try to
> narrow down the possible differences between your build and the official
> Cygwin build.  To do that, I'd probably start with getting the source
> for the official Cygwin build, compiling it using Cygport (`cygport
> vim.cygport prep compile install package`), then "installing" it as if
> it were a regular Cygwin package (`tar -xaf vim-*/dist/vim/vim-*.tar.*
> -C /` is close enough for most purposes).

I thought about that, too, but didn't know how to do it and hadn't
waded into the cygport docs.  Thanks for the instructions.

If the problem is due to a difference in the way I built my version,
it appears from my strace of bash that it happens in the code that
precedes vim's main().  I don't know what that would be.  Perhaps it
does have something to do with preparing the program for debugging.

Regards,
Gary

Re: Bash runs my vim slower than Cygwin's vim

[Gary Johnson]

On 2022-03-11, Gary Johnson wrote:
> On 2022-03-11, Adam Dinwoodie wrote:
> > On Thu, Mar 10, 2022 at 04:55:40PM -0800, Gary Johnson wrote:

> > > So, does anyone know why is takes so much longer for bash to run the
> > > vim I built than the official Cygwin vim?  More importantly, how do
> > > I fix this?

> > - Cygwin packages built using Cygport and packaged for release will have
> >   the binaries stripped, removing debug symbols and the like and
> >   separating them into a different -debug package.  That means that the
> >   binaries that are loaded for day-to-day use are smaller, and may well
> >   mean they're faster too.
> 
> The Cygwin vim was built with -ggdb, but I didn't look for strip and
> Cygwin's file doesn't report whether or not binaries are stripped--
> it probably can't determine that.  I'll try stripping mine.

Just a quick update:  I stripped my version and the real time for my
benchmark test dropped from 1.42 s to 0.40 s.  Still not as low as
Cygwin's vim (0.12 s), but a substantial improvement.

Regards,
Gary

Re: Bash runs my vim slower than Cygwin's vim

[Gary Johnson]

On 2022-03-11, Gary Johnson wrote:
> On 2022-03-11, Gary Johnson wrote:
> > On 2022-03-11, Adam Dinwoodie wrote:
> > > On Thu, Mar 10, 2022 at 04:55:40PM -0800, Gary Johnson wrote:
> 
> > > > So, does anyone know why is takes so much longer for bash to run the
> > > > vim I built than the official Cygwin vim?  More importantly, how do
> > > > I fix this?
> 
> > > - Cygwin packages built using Cygport and packaged for release will have
> > >   the binaries stripped, removing debug symbols and the like and
> > >   separating them into a different -debug package.  That means that the
> > >   binaries that are loaded for day-to-day use are smaller, and may well
> > >   mean they're faster too.
> > 
> > The Cygwin vim was built with -ggdb, but I didn't look for strip and
> > Cygwin's file doesn't report whether or not binaries are stripped--
> > it probably can't determine that.  I'll try stripping mine.
> 
> Just a quick update:  I stripped my version and the real time for my
> benchmark test dropped from 1.42 s to 0.40 s.  Still not as low as
> Cygwin's vim (0.12 s), but a substantial improvement.

I installed cygport and built vim using Adam's command.  It wanted
some libraries that I don't have installed, such as for X, which
I don't use on Windows, so I modified vim.cygport to not require
those.  The result ran a little slower than /usr/bin/vim.  So to
really understand this, I will probably have to install those
libraries and run vim.cygport unmodified.

However, by changing CFLAGS to remove -g3 and add -O2 for my own
build, and by stripping the binary, the startup time for vim to edit
a particular file dropped from 8 seconds to 2 seconds, and even
using /usr/bin/vim takes 1.4 seconds, so I'm happy for now.

Thanks, Adam, for the help.

Regards,
Gary