MSYS2-packages: All tools from shell are very slow

Any tool I run in msys2 shell (ls, mv, …) are very slow. Simply ls takes something like 3 seconds.

Running “strace ls” I see following output:

   15   39327 [main] ls 7460 DLL build:    2014-11-21 06:38
   16   39343 [main] ls 7460 dtable::extend: size 32, fds 0x1802FB488
  381   39724 [main] ls 7460 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\msys-07c9b4f1c823d951-lpc
   40   39764 [main] ls 7460 transport_layer_pipes::connect: Error opening the pipe (2)
   31   39795 [main] ls 7460 client_request::make_request: cygserver un-available
--- Process 7460, exception 00000000 at 000007FEFD22940D
1804450 1844245 [main] ls 7460 reg_key::build_reg: failed to create key ServicesForNFS in the registry
 2011 1846256 [ldap_init] ls 7460 cygthread::stub: thread 'ldap_init', id 0x2410, stack_ptr 0x2FCAC90
310497 2156753 [main] ls 7460 pwdgrp::fetch_account_from_windows: line: <...USERNAME...:*:1599881:1049089:....SOME_REGISTRY_KEY...:/home/...USERNAME...:/usr/bin/bash>
 6571 2163324 [main] ls 7460 pwdgrp::fetch_account_from_windows: line: <Domain Users:S-1-5-21-1915207013-2615040368-3076929458-513:1049089:>
  768 2164092 [main] ls 7460 pwdgrp::fetch_account_from_windows: line: <Performance Log Users:S-1-5-32-559:559:>
  402 2164494 [main] ls 7460 pwdgrp::fetch_account_from_windows: line: <Users:S-1-5-32-545:545:>

Could slowness be related to this? I am on non-admin user on this machine… Can that be avoided?

About this issue

Original URL
State: open
Created 10 years ago
Reactions: 14
Comments: 59 (26 by maintainers)

Most upvoted comments

I also faced the same issue with KrullKorg and legends2k’s case. I found that expansion of ~* was very slow. I had to update /etc/passwd and /etc/group, then disable db in nsswitch.conf. More detail: https://gist.github.com/k-takata/9b8d143f0f3fef5abdab

+10

k-takata on May 13, 2015

i “solved” disabling db in nsswitch.conf

KrullBorg on Jan 21, 2015

With a new msys2 installation today, I observed every process, the initial bash.exe spawned by mintty.exe as well as every process spawned by bash, taking ~1s to ~3s to start. strace bash 2>&1 | ts revealed all the time was spent before the first line out of output from strace, suggesting it was part of the process startup itself.

I tried the nsswitch.conf technique in the comments above but it did not change anything. (I believe Cygwin had got a patch to make the workaround unnecessary, and perhaps msys2 has had that same patch as well.)

So I traced bash.exe through procmon and observed it spending ~500ms on every startup enumerating ~8k files that match C:\Windows\System32\catroot\{F750E6C3-38EE-11D1-85E5-00C04FC295EE}\*.cat, each with a callstack containing appid.sys (the AppLocker driver). That led me to this page, and indeed my machine has AppLocker policies enabled (*). After code-signing all binaries under C:\msys64\usr\bin as that page suggests (cd C:\msys64\usr\bin\; gci -re *.exe | %{ &'C:\Program Files (x86)\Windows Kits\8.1\bin\x64\signtool.exe' sign /a /uw $_.FullName }), all msys2 process start nearly instantaneously.

(*) secpol.msc actually says there are no AppLocker policies, but Get-AppLockerPolicy -Effective clearly lists several.

Arnavion on Jun 12, 2018

Yeah, eventually I found the file and commented out ‘#db’ for the:‘group’. But that doesn’t help. Everything is extremely slow.

i2000s on Jun 30, 2017

Disabling db from both passwd and group fixed the issue but led to my username being unrecognised (bash prompt showed me as Unknown+User). However, the “fix” was to just disable db from group and leave passwd as it was, and this sped up MSYS2 utilities like diff, which, ls and also the startup of MSYS2 significantly.

legends2k on Feb 12, 2015

This is great. Commenting out “db” from nsswitch.conf helps. Now all operations are fast for me.

mmozeiko on Jan 21, 2015

Slow +1

act262 on Sep 27, 2022

msys2 in general is slow due to the POSIX emulation layer that it must do to translate ALL posix api’s into Window’s API

this INCLUDES the IO drivers and console input/output drivers among other heavy drivers/layers

I was talking about msys2 as a domain user, msys2 on normal windows installations is quick, so there is some networking happening, idk what, or maybe it’s the antivirus checking every I/O, 🤷

Kreijstal on Mar 11, 2024

The issue for Bash run this way is someone needs to modify Bash itself to fit more into how Windows is designed to handle subprocesses and other concerns. There’s no way around that. Until that happens this will always be slow.

Are we sure is bash? I just noticed something, when I run make it throws tons of exception in the background? I am not exactly sure what I’m doing, but I ran a strace make (because that’s what was being super slow).

And it looks like internally it spwns a bash shell and then it throws an insane amount of “internal exception”?

--- Process 14120 created
 3079   77327 [main] make 5649 child_info_spawn::worker: pid 5649, prog_arg /bin/bash, cmd line C:\msys64\usr\bin\bash.exe -c "echo  | cut -d- -f3")
--- Process 14120 loaded C:\Windows\System32\ntdll.dll at 00007ffb23350000
 1367   78694 [main] make 5649! child_info_spawn::worker: new process name \\?\C:\msys64\usr\bin\bash.exe
 2674   81368 [main] make 5649! child_info_spawn::worker: spawned windows pid 14120
  323   81691 [main] make 5649! child_info::sync: n 2, waiting for subproc_ready(0x218) and child process(0x224)
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\kernel32.dll at 00007ffb22350000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\KernelBase.dll at 00007ffb207e0000
--- Process 14120 (pid: 5649) thread 4020 created
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\user32.dll at 00007ffb21360000
--- Process 14120 (pid: 5649) loaded C:\msys64\usr\bin\msys-2.0.dll at 0000000180040000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\win32u.dll at 00007ffb21060000
--- Process 14120 (pid: 5649) thread 8148 created
--- Process 14120 (pid: 5649) thread 6616 created
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\gdi32.dll at 00007ffb22e10000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\gdi32full.dll at 00007ffb20d80000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\msvcp_win.dll at 00007ffb20fc0000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\ucrtbase.dll at 00007ffb20ea0000
    1       1 [main] bash (14120) **********************************************
  308     309 [main] bash (14120) Program name: C:\msys64\usr\bin\bash.exe (windows pid 14120)
  263     572 [main] bash (14120) OS version:   Windows NT-10.0
  307     879 [main] bash (14120) **********************************************
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\advapi32.dll at 00007ffb21a00000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\msvcrt.dll at 00007ffb22a30000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\sechost.dll at 00007ffb212b0000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\rpcrt4.dll at 00007ffb22e40000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\cryptbase.dll at 00007ffb1ffa0000
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\bcryptprimitives.dll at 00007ffb20d00000
23493   24372 [main] bash (14120) sigprocmask: 0 = sigprocmask (0, 0x0, 0x18031C470)
  484   24856 [main] bash (14120) child_copy: cygheap - hp 0x21C low 0x800000000, high 0x80000D3F0, res 1
  270   25126 [main] bash (14120) child_copy: done
  321   25447 [main] bash (14120) open_shared: name shared.5, shared 0x1A0000000 (wanted 0x1A0000000), h 0x11C, m 0, created 0
  283   25730 [main] bash (14120) user_heap_info::init: heap base 0xA00000000, heap top 0xA00000000, heap size 0x20000000 (536870912)
  353   26083 [main] bash (14120) open_shared: name (null), shared 0x1A1000000 (wanted 0x1A1000000), h 0x120, m 1, created 0
  267   26350 [main] bash (14120) user_info::create: opening user shared for '' at 0x1A1000000
  264   26614 [main] bash (14120) user_info::create: user shared version AB1FCCE8
  314   26928 [main] bash (14120) open_shared: name (null), shared 0x1A2000000 (wanted 0x1A2000000), h 0x214, m 2, created 0
  308   27236 [main] bash 5649 pinfo::thisproc: myself dwProcessId 14120
  324   27560 [main] bash 5649 open_shared: name (null), shared 0x1A3000000 (wanted 0x1A3000000), h 0x194, m 3, created 0
  283   27843 [main] bash 5649 open_shared: name cygpid.1995, shared 0x1A4000000 (wanted 0x1A4000000), h 0x128, m 6, created 0
  349   28192 [main] bash 5649 fhandler_base::fixup_after_exec: here for 'pipe:[51539614328]'
  305   28497 [main] bash 5649 open_shared: name cygpid.1995, shared 0x1A4010000 (wanted 0x1A4010000), h 0x128, m 6, created 0
  333   28830 [main] bash 5649 fhandler_base::fixup_after_exec: here for '/c/Users/et5341/source/windows/mystuff/Makefile'
  226   29056 [main] bash 5649 fhandler_base::fixup_after_exec: here for '/c/Users/et5341/source/windows/mystuff/cis.mk'
  191   29247 [main] bash 5649 fhandler_base::fixup_after_exec: here for '/c/Users/et5341/source/windows/mystuff/colours.mk'
  218   29465 [main] bash 5649 fhandler_base::fixup_after_exec: here for 'pipe:[51539614328]'
  264   29729 [main] bash 5649 fhandler_base::fixup_after_exec: here for 'pipe:[51539614328]'
  267   29996 [main] bash 5649 child_info::ready: signalled 0x218 that I was ready
66070  147761 [main] make 5649! child_info::sync: pid 14120, WFMO returned 0, exit_code 0x103, res 1
  334   30330 [main] bash 5649 fhandler_pipe::create: name \\.\pipe\msys-dd50a72ab4668b33-14120-sigwait, size 11440, mode PIPE_TYPE_MESSAGE
  420  148181 [main] make 5649! fhandler_base::close_with_arch: line 1181:  /dev/cons0<0x800008AB0> usecount + -1 = 2
  348   30678 [main] bash 5649 fhandler_pipe::create: pipe read handle 0x130
  348  148529 [main] make 5649! fhandler_base::close_with_arch: not closing archetype
  284   30962 [main] bash 5649 fhandler_pipe::create: CreateFile: name \\.\pipe\msys-dd50a72ab4668b33-14120-sigwait
  399  148928 [main] make 5649! fhandler_pipe::release_select_sem: close(PIPEW) release 2
  439   31401 [main] bash 5649 fhandler_pipe::create: pipe write handle 0x134
  341  149269 [main] make 5649! fhandler_base::close: closing 'pipe:[51539614328]' handle 0x2A8
  336   31737 [main] bash 5649 dll_crt0_0: finished dll_crt0_0 initialization
  364  149633 [main] make 5649! fhandler_base::close_with_arch: line 1181:  /dev/cons0<0x800008AB0> usecount + -1 = 1
  376  150009 [main] make 5649! fhandler_base::close_with_arch: not closing archetype
  326  150335 [main] make 5649! fhandler_base::close: closing '/c/Users/et5341/source/windows/mystuff/Makefile' handle 0x154
  363  150698 [main] make 5649! fhandler_base::close: closing '/c/Users/et5341/source/windows/mystuff/cis.mk' handle 0x15C
  296  150994 [main] make 5649! fhandler_base::close: closing '/c/Users/et5341/source/windows/mystuff/colours.mk' handle 0x160
  246  151240 [main] make 5649! fhandler_pipe::release_select_sem: close(PIPER) release 2
  247  151487 [main] make 5649! fhandler_base::close: closing 'pipe:[51539614328]' handle 0x170
  304  151791 [main] make 5649! fhandler_pipe::release_select_sem: close(PIPEW) release 1
--- Process 14120 (pid: 5649) loaded C:\Windows\System32\imm32.dll at 00007ffb230b0000
  392  152183 [main] make 5649! fhandler_base::close: closing 'pipe:[51539614328]' handle 0x17C
 3372  155555 [main] make 5649! proc_terminate: child_procs count 0
  327  155882 [main] make 5649! proc_terminate: leaving
  300  156182 [main] make 5649! pinfo::maybe_set_exit_code_from_windows: pid 5649, exit value - old 0x0, windows 0xDEADBEEF, MSYS 0x0
  354  156536 [main] make 5649! pinfo::exit: Calling dlls.cleanup_forkables n 0x4000000, exitcode 0x0
  303  156839 [main] make 5649! pinfo::exit: Calling ExitProcess n 0x4000000, exitcode 0x0
--- Process 14120 (pid: 5649), exception c0000005 at 0000000000000000
--- Process 12384 thread 14088 exited with status 0x0
--- Process 12384 thread 19736 exited with status 0x0
--- Process 12384 thread 17044 exited with status 0x0
--- Process 12384 thread 3152 exited with status 0x0
--- Process 14120 (pid: 5649), exception c0000005 at 00000001800616fc
--- Process 12384 exited with status 0x0
--- Process 14120 (pid: 5649), exception c0000005 at 00000001800616fc
--- Process 14120 (pid: 5649), exception c0000005 at 00000001800616fc
--- Process 14120 (pid: 5649), exception c0000005 at 00000001800616fc
--- Process 14120 (pid: 5649), exception c0000005 at 00000001800616fc
^^^^ this same exception with exact same code goes on for like a few hundreds lines ^^^^

Thoughts?

totszwai on May 11, 2023

I too experienced extreme slowness on Win 10. This fixed it for me:

mkpasswd > /etc/passwd mkgroup > /etc/group

Then comment out mentions of db in /etc/nsswitch.conf and restart msys2. Moving at a usable clip now.

ghost on Feb 8, 2021

I think the AV is called Avast. I have uninstalled it.

i2000s on Jul 17, 2017

@legends2k I think I have found the problem: my Anti-Virus software has been dragging every single one of my commands. Disabling it doesn’t change the game. Once I completely removed the anti-virus software, everything started working again. Just to let you know. Thanks.

i2000s on Jun 30, 2017

unfortunately now some commands are slower than some time ago; for example: ls, git status/diff, configure (autoreconf), gitk

KrullBorg on Apr 14, 2015