commands spends time in cygheap_user

[pen]

simple commands like ls taking long time in "cygheap_user". May i have some pointers to what to check?
Already checked path/cygcheck/nsswitch but all looks fine. here is sample strace.

      14    4973 [main] ls 9308 App version:  1007.32, api: 0.274
   14    4987 [main] ls 9308 DLL version:  2001.0, api: 0.287
   19    5006 [main] ls 9308 DLL build:    2015-07-14 21:26
   21    5027 [main] ls 9308 dtable::extend: size 32, fds 0x612EFB50
  222    5249 [main] ls 9308 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-685dc4bb75d52efd-lpc
   39    5288 [main] ls 9308 transport_layer_pipes::connect: Error opening the pipe (2)
   29    5317 [main] ls 9308 client_request::make_request: cygserver un-available
--- Process 9308 loaded C:\Windows\SysWOW64\advapi32.dll at 756D0000
--- Process 9308 loaded C:\Windows\SysWOW64\msvcrt.dll at 75490000
--- Process 9308 loaded C:\Windows\SysWOW64\sechost.dll at 77290000
--- Process 9308 loaded C:\Windows\SysWOW64\rpcrt4.dll at 75870000
--- Process 9308 loaded C:\Windows\SysWOW64\sspicli.dll at 75300000
--- Process 9308 loaded C:\Windows\SysWOW64\cryptbase.dll at 752F0000
--- Process 9308 thread 5864 created
 5919   11236 [sig] ls 9308 wait_sig: entering ReadFile loop, my_readsig 0x8C, my_sendsig 0x90
--- Process 9308 thread 7472 created
2441548 2452784 [main] ls 9308 cygheap_user::ontherange: what 2, pw 0x612EFCE8      <<<
  135 2452919 [main] ls 9308 cygheap_user::ontherange: HOME is already in the environment /home/pen
  308 2453227 [main] ls 9308 build_argv: argv[0] = 'ls'

[mku]

I got an update to Cygwin DLL version 2.2.0 (32bit) running on Win7 (64bit) and have a horrible slowdown too. (often more than 5 sec for an ls command. look at the following strace:)
+++ 8< ---------------------
   48   11503 [main] ls 110784 transport_layer_pipes::connect: Error opening the
   71   11574 [main] ls 110784 client_request::make_request: cygserver un-availa
--- Process 110784 loaded C:\Windows\SysWOW64\advapi32.dll at 75940000
--- Process 110784 loaded C:\Windows\SysWOW64\msvcrt.dll at 75DB0000
--- Process 110784 loaded C:\Windows\SysWOW64\sechost.dll at 75CE0000
--- Process 110784 loaded C:\Windows\SysWOW64\rpcrt4.dll at 75F10000
--- Process 110784 loaded C:\Windows\SysWOW64\sspicli.dll at 75490000
--- Process 110784 loaded C:\Windows\SysWOW64\cryptbase.dll at 75480000
--- Process 110784 thread 110968 created
4510641 4522215 [main] ls 110784 cygheap_user::ontherange: what 2, pw 0x612FFD30 <<<
  200 4522415 [main] ls 110784 cygheap_user::ontherange: HOME is already in the
 1484 4523899 [main] ls 110784 build_argv: argv[0] = 'ls'
  134 4524033 [main] ls 110784 build_argv: argv[1] = '-lrt'
--- 8< ---------------------

Does anybody care about that problem? What can I do?

[timhok]

I'am have same issue listed, win7 64x + Cygwin 2.871 64x

 53   33230 [main] cat 19972 pinfo_init: Set nice to 0
   33   33263 [main] cat 19972 pinfo_init: pid 19972, pgid 19972, process_state 0x41
   34   33297 [main] cat 19972 App version:  1007.32, api: 0.274
   34   33331 [main] cat 19972 DLL version:  2002.0, api: 0.289
   33   33364 [main] cat 19972 DLL build:    2015-08-03 12:51
   34   33398 [main] cat 19972 dtable::extend: size 32, fds 0x180326B80
--- Process 19972 loaded C:\Windows\System32\advapi32.dll at 000007FEFFDA0000
--- Process 19972 loaded C:\Windows\System32\msvcrt.dll at 000007FEFE220000
--- Process 19972 loaded C:\Windows\System32\sechost.dll at 000007FEFF050000
--- Process 19972 loaded C:\Windows\System32\rpcrt4.dll at 000007FEFF470000
--- Process 19972 thread 18892 created
42017455 42050853 [main] cat 19972 cygheap_user::ontherange: what 2, pw 0x180326150
  187 42051040 [main] cat 19972 cygheap_user::ontherange: Set HOME (from account db) to /home/%username%

[mku]

In order to find the reason for the delay in processing the ls command, I did some investigations with the following results:

As I wished to use cygwin in a local environment that is not permanently connected to AD (mobile device), I modified the file /etc/nsswitch.conf after having the long lasting ls command to the following contents:
    passwd:   files
    group:    files
After rebooting the effect remains (ls commands took about 5 sec to complete for a local directory with 10 files).

After that I enabled the VPN tunnel to the AD domain and tried the ls command again. To list the 10 files it now took only 0.9 sec.

After closing the VPN tunnel to the AD domain, I had the 5 sec for the ls of 10 files again. So the problem seems to relate to the accessibility of the AD domain.
I have the impression, that the ls command always tries to connect to the AD domain and only continues to work after it got a time out. The modification of nsswitch.conf seems to have no effect to that behaviour.

As this cygwin version is not usable for me, I restored an old backup (1.7.28).
The result is, that the same ls command now takes 0.020 sec. That means that the new 2.2 version is 250 times slower!
But now I would like to know where I can download a consistent 1.7.28 distribution to be independent of the actual cygwin distribution and do an installation from local directory.
Can somebody help or give a pointer?

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[mku]

Dear Corinna,
thanks for the tip, but I had done it before (and modified it to my Needs). To be safe, I did a complete fresh Installation and made the passwd and group files as described. But the result is the same as before (a ls command takes 5 to 10 secs to complete for a local Directory with 10 files). The main time lag is after the Win dll load:
+++ 8< -------------------
   46   12959 [main] ls 588804 client_request::make_request: cygserver un-available
--- Process 588804 loaded C:\Windows\SysWOW64\advapi32.dll at 76B80000
--- Process 588804 loaded C:\Windows\SysWOW64\msvcrt.dll at 762B0000
--- Process 588804 loaded C:\Windows\SysWOW64\sechost.dll at 75870000
--- Process 588804 loaded C:\Windows\SysWOW64\rpcrt4.dll at 76620000
--- Process 588804 loaded C:\Windows\SysWOW64\sspicli.dll at 75760000
--- Process 588804 loaded C:\Windows\SysWOW64\cryptbase.dll at 75750000
--- Process 588804 thread 588956 created
--- Process 588804 loaded C:\Windows\SysWOW64\netapi32.dll at 74E90000
--- Process 588804 loaded C:\Windows\SysWOW64\netutils.dll at 74E80000
--- Process 588804 loaded C:\Windows\SysWOW64\srvcli.dll at 74E60000
--- Process 588804 loaded C:\Windows\SysWOW64\wkscli.dll at 74E50000
--- Process 588804 loaded C:\Windows\SysWOW64\logoncli.dll at 727A0000
4519662 4532621 [main] ls 588804 pwdgrp::fetch_account_from_windows: line: <INTERAKTIV:S-1-5-4:4:>
  907 4533528 [main] ls 588804 pwdgrp::fetch_account_from_windows: line: <KONSOLENANMELDUNG:S-1-2-1:66049:>
  751 4534279 [main] ls 588804 pwdgrp::fetch_account_from_windows: line: <Authentifizierte Benutzer:S-1-5-11:11:>
  718 4534997 [main] ls 588804 pwdgrp::fetch_account_from_windows: line: <Diese Organisation:S-1-5-15:15:>
--- 8< --------------------
Now the "pwdgrp" logs are shown before the "cygheap_user::ontherange".

If I repeat the same ls command in a short timeframe (some seconds), the ls command is processed at normal Speed (e.g. 0.06 sec).

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[mku]

Oh, sorry. I did a fresh 2.2 install to avoid side effects from my previous updated one and forgot to modify the nsswitch.conf. After correcting it, the result now is the same from the time aspect but loading of the net dlls have now disappeared as expected.
+++ 8< -----
  280   44318 [main] ls 181944 client_request::make_request: cygserver un-availa
--- Process 181944 loaded C:\Windows\SysWOW64\advapi32.dll at 75400000
--- Process 181944 loaded C:\Windows\SysWOW64\msvcrt.dll at 76CB0000
--- Process 181944 loaded C:\Windows\SysWOW64\sechost.dll at 76A00000
--- Process 181944 loaded C:\Windows\SysWOW64\rpcrt4.dll at 75300000
--- Process 181944 loaded C:\Windows\SysWOW64\sspicli.dll at 750C0000
--- Process 181944 loaded C:\Windows\SysWOW64\cryptbase.dll at 750B0000
--- Process 181944 thread 186236 created
4525052 4569370 [main] ls 181944 cygheap_user::ontherange: what 2, pw 0x612FFCF0
  302 4569672 [main] ls 181944 cygheap_user::ontherange: HOME is already in the
--- 8< -----
I don't know how the delta time is calculated. As the time lag is always printed after loading the dlls, it may be that the log message is printed after the logged step has been completed. If that is true, the time lag may occur while loading one of the dlls or creating the thread.

As I mentioned before the same command repeated one second again shows normal behaviour (0.406s).
+++ 8< -----
  106   20307 [main] ls 201132 client_request::make_request: cygserver un-availa
--- Process 201132 loaded C:\Windows\SysWOW64\advapi32.dll at 75400000
--- Process 201132 loaded C:\Windows\SysWOW64\msvcrt.dll at 76CB0000
--- Process 201132 loaded C:\Windows\SysWOW64\sechost.dll at 76A00000
--- Process 201132 loaded C:\Windows\SysWOW64\rpcrt4.dll at 75300000
--- Process 201132 loaded C:\Windows\SysWOW64\sspicli.dll at 750C0000
--- Process 201132 loaded C:\Windows\SysWOW64\cryptbase.dll at 750B0000
--- Process 201132 thread 201240 created
 9195   29502 [main] ls 201132 cygheap_user::ontherange: what 2, pw 0x612FFCF0
   95   29597 [main] ls 201132 cygheap_user::ontherange: HOME is already in the
--- 8< -----
If you wait a longer period (e.g. 5 minutes), the first (longer) behaviour is shown.
As this time lag is not seen with Version 1.7.28 on the same machine, I assume that it has come with Version 2.2.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[mku]

I compared strace output between the 2.2 and 1.7.28 installation and it seems, that loading the dll files before the cygheap_user log entry is responsible for the time lag.
If I look to the strace output from 1.7.28 the following lines (without the dll loads) are shown:
+++ 8< ------
    31    9709 [main] ls 64316 pinfo_init: Set nice to 0
   19    9728 [main] ls 64316 pinfo_init: pid 64316, pgid 64316, process_state 0x41
   17    9745 [main] ls 64316 App version:  1007.10, api: 0.259
   19    9764 [main] ls 64316 DLL version:  1007.28, api: 0.271
   17    9781 [main] ls 64316 DLL build:    2014-02-09 21:06
   19    9800 [main] ls 64316 dtable::extend: size 32, fds 0x612AD6C4
  319   10119 [main] ls 64316 pwdgrp::load: \etc\passwd curr_lines 8
   30   10149 [main] ls 64316 pwdgrp::load: \etc\passwd load succeeded
  323   10472 [main] ls 64316 pwdgrp::load: \etc\group curr_lines 58
   35   10507 [main] ls 64316 pwdgrp::load: \etc\group load succeeded
   26   10533 [main] ls 64316 cygheap_user::ontherange: what 2, pw 0x8003A770
   25   10558 [main] ls 64316 cygheap_user::ontherange: HOME is already in the environment /home/
  120   10678 [main] ls 64316 internal_setlocale: Cygwin charset changed from UTF-8 to ISO-8859-1
   62   10740 [main] ls 64316 build_argv: argv[0] = 'ls'
   19   10759 [main] ls 64316 build_argv: argv[1] = '-lrt'
--- 8< -------
Yes, this Version has nsswitch.conf in the default configuration (with db entries) so you see the pwdgrp log entries but it is very fast.
Perhaps this helps in finding the problem.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[mku]

I hope, not to follow a red herring again, but found some interesting.

I did a fresh cygwin installation again but made an error not to copy my old .bashrc and .bashrc-profile files.
Within .bashrc I defined an alias for ls (ls='ls --color=auto --show-control-chars').
I noticed, that the time lag has went away. After a "ls --color=auto", the time lag appeared again.
Comparing the strace output with/without the color flag, I found that the time lag at "cygheap_user::ontherange" has gone and it now appeared at a ldap_bind [ldap_init] that was called in the context of a symbolic link to a directory on a network share. The previous strace logs did not show a time lag at this point, only at the cygheap_user entry.

I deleted the "ln -s" entry and did not notice this big time lag any more even with the color flag.

I restored the "old" v2.2.0 version and cannot find the previous logged time lag.
As no files within the cygwin directory structure has been modified, it seems, that some registry information has been "healed" by the multiple fresh installations.

PS: To do a fresh install I did a "backup" by renaming the original cygwin folder. The "restore" was done by renaming the fresh installed cygwin folder and renaming the previous "backuped" folder back to cygwin.

For me the issue is now closed. Thanks for your input.

Regards, Matthias

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[mku]

I changed cygwin1.dll to Version 2.2.1 and got the results shown in the attached log file (
cygwin-time-lag.txt).
I'm sorry to say that the problem has not disappeared with that patch.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[Corinna Vinschen-2]

CONTENTS DELETED

The author has deleted this message.

[mku]

Attached my console log (cygwin-time-lag.txt) to shorten this message.
nsswitch.conf contains only "files" entries. The time lag can be reproduced and is now shown at the "cygheap_user" log entry as described previously. I added the alias definition of 'ls' and the cygcheck info about the used cygwin1.dll.