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

[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 76B8
--- Process 588804 loaded C:\Windows\SysWOW64\msvcrt.dll at 762B
--- Process 588804 loaded C:\Windows\SysWOW64\sechost.dll at 7587
--- Process 588804 loaded C:\Windows\SysWOW64\rpcrt4.dll at 7662
--- Process 588804 loaded C:\Windows\SysWOW64\sspicli.dll at 7576
--- Process 588804 loaded C:\Windows\SysWOW64\cryptbase.dll at 7575
--- Process 588804 thread 588956 created
--- Process 588804 loaded C:\Windows\SysWOW64\netapi32.dll at 74E9
--- Process 588804 loaded C:\Windows\SysWOW64\netutils.dll at 74E8
--- Process 588804 loaded C:\Windows\SysWOW64\srvcli.dll at 74E6
--- Process 588804 loaded C:\Windows\SysWOW64\wkscli.dll at 74E5
--- Process 588804 loaded C:\Windows\SysWOW64\logoncli.dll at 727A
4519662 4532621 [main] ls 588804 pwdgrp::fetch_account_from_windows: line:

  907 4533528 [main] ls 588804 pwdgrp::fetch_account_from_windows: line:

  751 4534279 [main] ls 588804 pwdgrp::fetch_account_from_windows: line:

  718 4534997 [main] ls 588804 pwdgrp::fetch_account_from_windows: line:

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

[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 7540
--- Process 181944 loaded C:\Windows\SysWOW64\msvcrt.dll at 76CB
--- Process 181944 loaded C:\Windows\SysWOW64\sechost.dll at 76A0
--- Process 181944 loaded C:\Windows\SysWOW64\rpcrt4.dll at 7530
--- Process 181944 loaded C:\Windows\SysWOW64\sspicli.dll at 750C
--- Process 181944 loaded C:\Windows\SysWOW64\cryptbase.dll at 750B
--- 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 7540
--- Process 201132 loaded C:\Windows\SysWOW64\msvcrt.dll at 76CB
--- Process 201132 loaded C:\Windows\SysWOW64\sechost.dll at 76A0
--- Process 201132 loaded C:\Windows\SysWOW64\rpcrt4.dll at 7530
--- Process 201132 loaded C:\Windows\SysWOW64\sspicli.dll at 750C
--- Process 201132 loaded C:\Windows\SysWOW64\cryptbase.dll at 750B
--- 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

[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< --
319709 [main] ls 64316 pinfo_init: Set nice to 0
   199728 [main] ls 64316 pinfo_init: pid 64316, pgid 64316,
process_state 0x41
   179745 [main] ls 64316 App version:  1007.10, api: 0.259
   199764 [main] ls 64316 DLL version:  1007.28, api: 0.271
   179781 [main] ls 64316 DLL build:2014-02-09 21:06
   199800 [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

[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

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




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

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



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

[mku]

Congratulation! You did it!

As you can see from the attached logfile ( 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