commands spends time in cygheap_user

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'





--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[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?



--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120365.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 1036 bytes --]

On Aug  7 01:48, mku wrote:
> 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. 

Sounds like you forgot to create correct /etc/passwd and /etc/group
files.  Switch on your VPN and call

  $ mkpasswd -l -d > /etc/passwd
  $ mkgroup -l -d > /etc/group


Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[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).






--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120377.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 2428 bytes --]

On Aug  7 12:51, mku wrote:
> 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".

Something's wrong with your settings in /etc/nsswitch.conf.  If the
settings are correct:

  passwd: files
  group: files

then the method pwdgrp::fetch_account_from_windows() will never be
called.  It appears that the nsswitch.conf setting is not right, so
the default setting is used:

  passwd: files db
  group: files db


Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[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.




--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120403.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 2859 bytes --]

On Aug 10 05:00, mku wrote:
> 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.

Well, it might have been introduced by *any* version later than 1.7.28.
It's very unlikley that this has been introduced by 2.2.0.  From the
above output it's not clear where it hangs.  I'll try to reproduce it
later this week.


Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[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.



--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120458.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 2008 bytes --]

On Aug 12 04:59, mku wrote:
> 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.

Thanks, but I think this is a red herring.  The strace from 1.7.28
didn't even print the dll loads.  This is an extension to strace which
has been added with Cygwin 2.1.0.


Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[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



--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120519.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 1842 bytes --]

On Aug 14 06:49, mku wrote:
> 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.

Thank you for this important point.  That gives me an idea what
happens and I guess this is something which needs fixing.  These
checks should also only happen if passwd/group in nsswitch.conf
are set to "db".


Thanks,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 2270 bytes --]

On Aug 14 17:48, Corinna Vinschen wrote:
> On Aug 14 06:49, mku wrote:
> > 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.
> 
> Thank you for this important point.  That gives me an idea what
> happens and I guess this is something which needs fixing.  These
> checks should also only happen if passwd/group in nsswitch.conf
> are set to "db".

I just checked in a patch to address this issue, and I just created a
new developer snapshot for testing.

Can you reproduce the situation by recreating the symlink and try again?
If you can reproduce it, can you give the latest Cygwin DLL from the
developer snapshot page https://cygwin.com/snapshots/ a try?


Thanks,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 2481 bytes --]

On Aug 14 22:20, Corinna Vinschen wrote:
> On Aug 14 17:48, Corinna Vinschen wrote:
> > On Aug 14 06:49, mku wrote:
> > > 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.
> > 
> > Thank you for this important point.  That gives me an idea what
> > happens and I guess this is something which needs fixing.  These
> > checks should also only happen if passwd/group in nsswitch.conf
> > are set to "db".
> 
> I just checked in a patch to address this issue, and I just created a
> new developer snapshot for testing.
> 
> Can you reproduce the situation by recreating the symlink and try again?
> If you can reproduce it, can you give the latest Cygwin DLL from the
> developer snapshot page https://cygwin.com/snapshots/ a try?

The new 2.2.1-0.1 test release contains this fix as well.  Please give
it a try.


Thanks,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[mku]

I changed cygwin1.dll to Version 2.2.1 and got the results shown in the
attached log file (
cygwin-time-lag.txt
<http://cygwin.1069669.n5.nabble.com/file/n120553/cygwin-time-lag.txt>  ).
I'm sorry to say that the problem has not disappeared with that patch.




--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120553.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 726 bytes --]

On Aug 16 05:35, mku wrote:
> I changed cygwin1.dll to Version 2.2.1 and got the results shown in the
> attached log file (
> cygwin-time-lag.txt
> <http://cygwin.1069669.n5.nabble.com/file/n120553/cygwin-time-lag.txt>  ).
> I'm sorry to say that the problem has not disappeared with that patch.


Too bad, I thought skipping the SID<->uid mapping per RFC 2307 is the
culprit.

Are you sure your /etc/nsswitch.conf is set to

  passwd: files
  group: files

Can you print it out, please?

I'll try to reproduce this again in the next few days.


Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 863 bytes --]

On Aug 17 10:07, Corinna Vinschen wrote:
> On Aug 16 05:35, mku wrote:
> > I changed cygwin1.dll to Version 2.2.1 and got the results shown in the
> > attached log file (
> > cygwin-time-lag.txt
> > <http://cygwin.1069669.n5.nabble.com/file/n120553/cygwin-time-lag.txt>  ).
> > I'm sorry to say that the problem has not disappeared with that patch.
> 
> 
> Too bad, I thought skipping the SID<->uid mapping per RFC 2307 is the
> culprit.

s/is the culprit/fixes the problem.

> 
> Are you sure your /etc/nsswitch.conf is set to
> 
>   passwd: files
>   group: files
> 
> Can you print it out, please?
> 
> I'll try to reproduce this again in the next few days.
> 
> 
> Corinna
> 
> -- 
> Corinna Vinschen                  Please, send mails regarding Cygwin to
> Cygwin Maintainer                 cygwin AT cygwin DOT com
> Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[mku]

Attached my console log ( cygwin-time-lag.txt
<http://cygwin.1069669.n5.nabble.com/file/n120585/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.



--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120585.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 1591 bytes --]

On Aug 17 10:13, Corinna Vinschen wrote:
> On Aug 17 10:07, Corinna Vinschen wrote:
> > On Aug 16 05:35, mku wrote:
> > > I changed cygwin1.dll to Version 2.2.1 and got the results shown in the
> > > attached log file (
> > > cygwin-time-lag.txt
> > > <http://cygwin.1069669.n5.nabble.com/file/n120553/cygwin-time-lag.txt>  ).
> > > I'm sorry to say that the problem has not disappeared with that patch.
> > 
> > 
> > Too bad, I thought skipping the SID<->uid mapping per RFC 2307 is the
> > culprit.
> 
> s/is the culprit/fixes the problem.
> 
> > 
> > Are you sure your /etc/nsswitch.conf is set to
> > 
> >   passwd: files
> >   group: files
> > 
> > Can you print it out, please?
> > 
> > I'll try to reproduce this again in the next few days.

I managed to reproduce the issue and I think I found the actual problem
here.  When trying to create the supplementary group list of the current
user, Cygwin called LookupAccountSids indiscriminately.  If you don't
have access to your AD, this call is bound to take some time, 5 to 10
secs in my testing.

I changed the code so that when "group: db" is set in /etc/nsswitch.conf
it will only utilize /etc/group to fetch group information.

I uploaded a new developer snapshot containing this patch to
https://cygwin.com/snapshots/  Please give it a try.  For testing, just
replace your current DLL with the snapshot DLL temporarily.


Thanks,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 1765 bytes --]

On Aug 17 22:55, Corinna Vinschen wrote:
> On Aug 17 10:13, Corinna Vinschen wrote:
> > On Aug 17 10:07, Corinna Vinschen wrote:
> > > On Aug 16 05:35, mku wrote:
> > > > I changed cygwin1.dll to Version 2.2.1 and got the results shown in the
> > > > attached log file (
> > > > cygwin-time-lag.txt
> > > > <http://cygwin.1069669.n5.nabble.com/file/n120553/cygwin-time-lag.txt>  ).
> > > > I'm sorry to say that the problem has not disappeared with that patch.
> > > 
> > > 
> > > Too bad, I thought skipping the SID<->uid mapping per RFC 2307 is the
> > > culprit.
> > 
> > s/is the culprit/fixes the problem.
> > 
> > > 
> > > Are you sure your /etc/nsswitch.conf is set to
> > > 
> > >   passwd: files
> > >   group: files
> > > 
> > > Can you print it out, please?
> > > 
> > > I'll try to reproduce this again in the next few days.
> 
> I managed to reproduce the issue and I think I found the actual problem
> here.  When trying to create the supplementary group list of the current
> user, Cygwin called LookupAccountSids indiscriminately.  If you don't
> have access to your AD, this call is bound to take some time, 5 to 10
> secs in my testing.
> 
> I changed the code so that when "group: db" is set in /etc/nsswitch.conf

uhm, make that

  ...when "group: files" is set...

> it will only utilize /etc/group to fetch group information.
> 
> I uploaded a new developer snapshot containing this patch to
> https://cygwin.com/snapshots/  Please give it a try.  For testing, just
> replace your current DLL with the snapshot DLL temporarily.


Thanks,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[mku]

Congratulation! You did it!

As you can see from the attached logfile ( cygwin-time-lag.txt
<http://cygwin.1069669.n5.nabble.com/file/n120626/cygwin-time-lag.txt>  )
the time lag went away after replacing cygwin1.dll with the 20150817
snapshot.

Many thanks,
Matthias



--
View this message in context: http://cygwin.1069669.n5.nabble.com/commands-spends-time-in-cygheap-user-tp119766p120626.html
Sent from the Cygwin list mailing list archive at Nabble.com.

--
Problem reports:       http://cygwin.com/problems.html
FAQ:                   http://cygwin.com/faq/
Documentation:         http://cygwin.com/docs.html
Unsubscribe info:      http://cygwin.com/ml/#unsubscribe-simple

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 578 bytes --]

On Aug 18 01:17, mku wrote:
> Congratulation! You did it!
> 
> As you can see from the attached logfile ( cygwin-time-lag.txt
> <http://cygwin.1069669.n5.nabble.com/file/n120626/cygwin-time-lag.txt>  )
> the time lag went away after replacing cygwin1.dll with the 20150817
> snapshot.

Good news, so you can eventually drop using 1.7.28 :)

I'll release 2.2.1 pretty soon now, maybe even today.


Thanks,
Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]

Re: commands spends time in cygheap_user

[Corinna Vinschen]

[-- Attachment #1: Type: text/plain, Size: 3359 bytes --]

On Aug 10 18:01, Corinna Vinschen wrote:
> On Aug 10 05:00, mku wrote:
> > 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.
> 
> Well, it might have been introduced by *any* version later than 1.7.28.
> It's very unlikley that this has been introduced by 2.2.0.  From the
> above output it's not clear where it hangs.  I'll try to reproduce it
> later this week.

Except, I can't.  Under the same circumstances, with nsswitch.conf

  passwd: files
  group: files

and the network connection to my AD disabled, I don't encounter any
noticable lag, not even after waiting a long time to get rid of
potentially cached info.

Any chance this behaviour is triggered by some virus scanner or
something like that?


Corinna

-- 
Corinna Vinschen                  Please, send mails regarding Cygwin to
Cygwin Maintainer                 cygwin AT cygwin DOT com
Red Hat

[-- Attachment #2: Type: application/pgp-signature, Size: 819 bytes --]