* long I/O delays when strace is running
@ 2017-04-20 18:13 Daniel Santos
2017-04-21 0:11 ` Gluszczak, Glenn
0 siblings, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-20 18:13 UTC (permalink / raw)
To: cygwin
Well I've solved one problem, but now I have another one. To try to
understand why except is getting broken pipes (child processes are
"going away"), I modified DejaGNU's /usr/bin/runtest so that it would
strace each except process:
-exec "$expectbin" $debug -- "$runpath"/runtest.exp $target ${1+"$@"}
+exec strace --output=/tmp/runtest.$$.log --trace-children
--mask=startup $expectbin $debug -- $runpath/runtest.exp $target ${1+"$@"}
However, when I run make -kj8 check after this, Cygwin processes that do
file I/O and even ps become very unresponsive and CPU utilization is low
(not to say that DejaGNU is good at balancing the test load). If I hit
ctrl-C on the make process, it won't exit for somewhere around 30
seconds. I am able to reproduce this to some degree with this simple
snippet, although the delays aren't as long as doing the above:
for ((i = 0; i < 64; ++i)); do strace --output=/tmp/sleep.$$.log
--trace-children --mask=startup sleep 64; done
Can anybody try this and see if they get delays when running ps -ef or
some such?
Thanks,
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* RE: long I/O delays when strace is running
2017-04-20 18:13 long I/O delays when strace is running Daniel Santos
@ 2017-04-21 0:11 ` Gluszczak, Glenn
2017-04-21 7:57 ` Daniel Santos
0 siblings, 1 reply; 15+ messages in thread
From: Gluszczak, Glenn @ 2017-04-21 0:11 UTC (permalink / raw)
To: cygwin
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 2071 bytes --]
I haven't run Cygwin Expect for about 6 moths on Windows but it was behaving fine last time I did.
One thing I am aware of is you can't interrupt sleep in TCL. The sleep must
complete until the Control C is processed (regardless of whether you redirected signals
to your own routines). Otherwise signals seemed to be processed immediately.
Perhaps some other service is interfering. You may want to disable other services.
Glenn
================================================================
Well I've solved one problem, but now I have another one. To try to understand why except is getting broken pipes (child processes are "going away"), I modified DejaGNU's /usr/bin/runtest so that it would strace each except process:
-exec "$expectbin" $debug -- "$runpath"/runtest.exp $target ${1+"$@"}
+exec strace --output=/tmp/runtest.$$.log --trace-children
--mask=startup $expectbin $debug -- $runpath/runtest.exp $target ${1+"$@"}
However, when I run make -kj8 check after this, Cygwin processes that do
file I/O and even ps become very unresponsive and CPU utilization is low
(not to say that DejaGNU is good at balancing the test load). If I hit
ctrl-C on the make process, it won't exit for somewhere around 30
seconds. I am able to reproduce this to some degree with this simple
snippet, although the delays aren't as long as doing the above:
for ((i = 0; i < 64; ++i)); do strace --output=/tmp/sleep.$$.log
--trace-children --mask=startup sleep 64; done
Can anybody try this and see if they get delays when running ps -ef or
some such?
Thanks,
Daniel
--
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
\0ТÒÐÐ¥\a&ö&ÆVÒ\a&W\x06÷'G3¢\x02\x02\x02\x02\x02\x02\x06‡GG\x03¢òö7–wv–âæ6öÒ÷\a&ö&ÆV×2æ‡FÖÀФd\x15\x13¢\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x02\x06‡GG\x03¢òö7–wv–âæ6öÒöf\x17\x12ðФFö7VÖVçF\x17F–öã¢\x02\x02\x02\x02\x02\x02\x02\x02\x06‡GG\x03¢òö7–wv–âæ6öÒöFö72æ‡FÖÀÐ¥Vç7V'67&–&R\x06–æfó¢\x02\x02\x02\x02\x02\x06‡GG\x03¢òö7–wv–âæ6öÒöÖÂò7Vç7V'67&–&R×6–×\x06ÆPÐ Ð
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-21 0:11 ` Gluszczak, Glenn
@ 2017-04-21 7:57 ` Daniel Santos
2017-04-21 9:38 ` Daniel Santos
0 siblings, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-21 7:57 UTC (permalink / raw)
To: cygwin
On 04/20/2017 08:43 AM, Gluszczak, Glenn wrote:
> I haven't run Cygwin Expect for about 6 moths on Windows but it was behaving fine last time I did.
> One thing I am aware of is you can't interrupt sleep in TCL. The sleep must
> complete until the Control C is processed (regardless of whether you redirected signals
> to your own routines). Otherwise signals seemed to be processed immediately.
Please note that my simplified test case isn't using expect, but the
standard /usr/bin/sleep.exe -- this is just to have strace run and trace
for a longer amount of time in order to expose the problem. (it did get
broken into a new line though, so add a backslash:
> for ((i = 0; i < 64; ++i)); do strace --output=/tmp/sleep.$$.log \
> --trace-children --mask=startup sleep 64; done
> Perhaps some other service is interfering. You may want to disable other services.
>
> Glenn
I usually disable most services, I can probably disable a few more, but
I would like if somebody can run the above test case in one terminal
windows and in the other terminal window do a simple ps -ef and let me
know if ps responds immediately or has a delay. I am using Windows 7,
so it could be isolated to that windows version as well. When I do
this, ps has a 3 second delay while in
fhandler_base_overlapped::wait_overlapped, but I've seen this delay in
other processes while calling something like "open_shared."
Anyway, I'm going to try to find another simple test case that causes
more of a drastic delay.
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-21 7:57 ` Daniel Santos
@ 2017-04-21 9:38 ` Daniel Santos
2017-04-21 11:06 ` Daniel Santos
0 siblings, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-21 9:38 UTC (permalink / raw)
To: cygwin
[-- Attachment #1: Type: text/plain, Size: 2249 bytes --]
On 04/20/2017 09:38 PM, Daniel Santos wrote:
> I usually disable most services, I can probably disable a few more
Actually, I was wrong as I had re-enabled a lot of services to try some
ms debugging tools, but I've pared it down to these and the problem
still happens:
C:\Users\daniel>net start
These Windows services are started:
Application Experience
Application Information
COM+ Event System
Cygserver 64
CYGWIN sshd 64
DCOM Server Process Launcher
DHCP Client
Group Policy Client
Network Connections
Network List Service
Network Location Awareness
Network Store Interface Service
Plug and Play
Power
Remote Procedure Call (RPC)
RPC Endpoint Mapper
Security Accounts Manager
Shell Hardware Detection
User Profile Service
Windows Management Instrumentation
Also, I'm running this in a VM, so I tried disabling the virtio driver
to try to rule that out and the problem is still occurs. The following
bash script does a much better job of producing the problem:
#!/bin/bash
exec_strace_sleep ()
{
exec strace --output=/tmp/sleep.$$-$1.log --trace-children
--mask=startup sleep 64
}
for ((i = 0; i < 8; ++i)); do
exec_strace_sleep $i &
done
wait
This script makes any cygwin process doing file I/O practically grind to
a halt. I can also demonstrate the problem running strace on ps alone:
strace --trace-children --output=/tmp/ps.log --mask=all ps -ef
Here is the interesting part of the log:
84 45292 [main] ps 1296 pinfo::init: execed process windows pid
380, cygwin pid 340
70 45362 [main] ps 1296 open_shared: name cygpid.340, n 340,
shared 0x30000 (wanted 0x0), h 0xEC, *m 6
77 45439 [main] ps 1296 open_shared: name cygpid.1044, n 1044,
shared 0x30000 (wanted 0x0), h 0xEC, *m 6
3119382 3164821 [main] ps 1296 open_shared: name cygpid.1576, n 1576,
shared 0x30000 (wanted 0x0), h 0xEC, *m 6
821 3165642 [main] ps 1296 open_shared: name cygpid.1420, n 1420,
shared 0x30000 (wanted 0x0), h 0xEC, *m 6
232 3165874 [main] ps 1296 pinfo::init: execed process windows pid
1420, cygwin pid 1468
196 3166070 [main] ps 1296 open_shared: name cygpid.1468, n 1468,
shared 0x30000 (wanted 0x0), h 0xEC, *m 6
Daniel
[-- Attachment #2: ps.log --]
[-- Type: text/x-log, Size: 48605 bytes --]
--- Process 1296 created
--- Process 1296 loaded C:\Windows\System32\ntdll.dll at 0000000076DD0000
--- Process 1296 loaded C:\Windows\System32\kernel32.dll at 0000000076CB0000
--- Process 1296 loaded C:\Windows\System32\KernelBase.dll at 000007FEFCED0000
--- Process 1296 loaded D:\cygwin64\bin\cygwin1.dll at 0000000180040000
--- Process 1296 loaded C:\Windows\System32\advapi32.dll at 000007FEFD920000
--- Process 1296 loaded C:\Windows\System32\msvcrt.dll at 000007FEFE790000
--- Process 1296 loaded C:\Windows\System32\sechost.dll at 000007FEFEC20000
--- Process 1296 loaded C:\Windows\System32\rpcrt4.dll at 000007FEFD4C0000
--- Process 1296 loaded C:\Windows\System32\psapi.dll at 0000000076F90000
13 13 [main] ps (1296) **********************************************
234 247 [main] ps (1296) Program name: D:\cygwin64\bin\ps.exe (windows pid 1296)
78 325 [main] ps (1296) OS version: Windows NT-6.1
65 390 [main] ps (1296) **********************************************
171 561 [main] ps (1296) sigprocmask: 0 = sigprocmask (0, 0x0, 0x1802DCBD0)
370 931 [main] ps 1296 open_shared: name shared.5, n 5, shared 0x180030000 (wanted 0x180030000), h 0x68, *m 6
176 1107 [main] ps 1296 user_heap_info::init: heap base 0x600000000, heap top 0x600000000, heap size 0x20000000 (536870912)
96 1203 [main] ps 1296 open_shared: name S-1-5-21-1442263037-415188738-1185266682-1000.1, n 1, shared 0x180020000 (wanted 0x180020000), h 0x64, *m 6
68 1271 [main] ps 1296 user_info::create: opening user shared for 'S-1-5-21-1442263037-415188738-1185266682-1000' at 0x180020000
66 1337 [main] ps 1296 user_info::create: user shared version AB1FCCE8
91 1428 [main] ps 1296 fhandler_pipe::create: name \\.\pipe\cygwin-f76db13c759b51fa-1296-sigwait, size 11440, mode PIPE_TYPE_MESSAGE
185 1613 [main] ps 1296 fhandler_pipe::create: pipe read handle 0x7C
79 1692 [main] ps 1296 fhandler_pipe::create: CreateFile: name \\.\pipe\cygwin-f76db13c759b51fa-1296-sigwait
152 1844 [main] ps 1296 fhandler_pipe::create: pipe write handle 0x80
103 1947 [main] ps 1296 dll_crt0_0: finished dll_crt0_0 initialization
--- Process 1296 thread 1116 created
2239 4186 [sig] ps 1296 wait_sig: entering ReadFile loop, my_readsig 0x7C, my_sendsig 0x80
201 4387 [main] ps 1296 time: 1492747214 = time(0x0)
286 4673 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\home\daniel, 0x0, no-add-slash)
176 4849 [main] ps 1296 normalize_win32_path: D:\cygwin64\home\daniel = normalize_win32_path (D:\cygwin64\home\daniel)
97 4946 [main] ps 1296 mount_info::conv_to_posix_path: /home/daniel = conv_to_posix_path (D:\cygwin64\home\daniel)
188 5134 [main] ps 1296 sigprocmask: 0 = sigprocmask (0, 0x0, 0x600018130)
533 5667 [main] ps 1296 _cygwin_istext_for_stdio: fd 0: not open
92 5759 [main] ps 1296 _cygwin_istext_for_stdio: fd 1: not open
89 5848 [main] ps 1296 _cygwin_istext_for_stdio: fd 2: not open
279 6127 [main] ps (1296) open_shared: name cygpid.1296, n 1296, shared 0x180010000 (wanted 0x180010000), h 0xBC, *m 2
124 6251 [main] ps (1296) time: 1492747214 = time(0x0)
101 6352 [main] ps 1296 pinfo::thisproc: myself dwProcessId 1296
120 6472 [main] ps 1296 environ_init: GetEnvironmentStrings returned 0x1AA1090
346 6818 [main] ps 1296 win32env_to_cygenv: 0x6000284F0: ALLUSERSPROFILE=C:\ProgramData
171 6989 [main] ps 1296 win32env_to_cygenv: 0x600028520: APPDATA=C:\Users\daniel\AppData\Roaming
185 7174 [main] ps 1296 win32env_to_cygenv: 0x600028550: COMPUTERNAME=WIN7PRO
205 7379 [main] ps 1296 win32env_to_cygenv: 0x600028570: COMSPEC=C:\Windows\system32\cmd.exe
176 7555 [main] ps 1296 parse_options: glob (called func)
168 7723 [main] ps 1296 parse_options: export
172 7895 [main] ps 1296 parse_options: returning
87 7982 [main] ps 1296 win32env_to_cygenv: 0x6000285A0: CYGWIN=noglob export detect_bloda
182 8164 [main] ps 1296 win32env_to_cygenv: 0x600028610: CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files
268 8432 [main] ps 1296 win32env_to_cygenv: 0x600028660: COMMONPROGRAMFILES=C:\Program Files\Common Files
177 8609 [main] ps 1296 win32env_to_cygenv: 0x6000286A0: CommonProgramW6432=C:\Program Files\Common Files
174 8783 [main] ps 1296 win32env_to_cygenv: 0x6000286E0: EDITOR=/usr/bin/vim
168 8951 [main] ps 1296 win32env_to_cygenv: 0x600028700: EXECIGNORE=*.dll
177 9128 [main] ps 1296 win32env_to_cygenv: 0x600028720: FP_NO_HOST_CHECK=NO
171 9299 [main] ps 1296 getwinenv: can't set native for HOME= since no environ yet
89 9388 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\home\daniel, 0x10000000, no-add-slash)
84 9472 [main] ps 1296 normalize_win32_path: D:\cygwin64\home\daniel = normalize_win32_path (D:\cygwin64\home\daniel)
88 9560 [main] ps 1296 mount_info::conv_to_posix_path: /home/daniel = conv_to_posix_path (D:\cygwin64\home\daniel)
243 9803 [main] ps 1296 win_env::add_cache: posix /home/daniel
87 9890 [main] ps 1296 win_env::add_cache: native HOME=D:\cygwin64\home\daniel
87 9977 [main] ps 1296 posify_maybe: env var converted to HOME=/home/daniel
259 10236 [main] ps 1296 win32env_to_cygenv: 0x6000287C0: HOME=/home/daniel
201 10437 [main] ps 1296 win32env_to_cygenv: 0x600028740: HOMEDRIVE=D:
166 10603 [main] ps 1296 win32env_to_cygenv: 0x6000287E0: HOMEPATH=\cygwin64\home\daniel
169 10772 [main] ps 1296 win32env_to_cygenv: 0x600028810: HOSTNAME=win7pro
169 10941 [main] ps 1296 win32env_to_cygenv: 0x600028830: INFOPATH=/usr/local/info:/usr/share/info:/usr/info
179 11120 [main] ps 1296 win32env_to_cygenv: 0x600028870: LANG=en_US.UTF-8
170 11290 [main] ps 1296 win32env_to_cygenv: 0x600028890: LOCALAPPDATA=C:\Users\daniel\AppData\Local
195 11485 [main] ps 1296 win32env_to_cygenv: 0x6000288D0: LOGNAME=daniel
174 11659 [main] ps 1296 win32env_to_cygenv: 0x6000288F0: LOGONSERVER=\\win7pro
168 11827 [main] ps 1296 win32env_to_cygenv: 0x600028910: MAIL=/var/spool/mail//daniel
168 11995 [main] ps 1296 win32env_to_cygenv: 0x600028940: NUMBER_OF_PROCESSORS=8
179 12174 [main] ps 1296 win32env_to_cygenv: 0x600028960: OLDPWD=/home/daniel
186 12360 [main] ps 1296 win32env_to_cygenv: 0x600028980: ORIGINAL_PATH=/bin:/d/cygwin32/lib/gcc/i686-pc-cygwin/5.4.0:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0:/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit
178 12538 [main] ps 1296 win32env_to_cygenv: 0x600028A70: OS=Windows_NT
183 12721 [main] ps 1296 getwinenv: can't set native for PATH= since no environ yet
179 12900 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\home\daniel\bin, 0x10000100, no-add-slash)
91 12991 [main] ps 1296 normalize_win32_path: D:\cygwin64\home\daniel\bin = normalize_win32_path (D:\cygwin64\home\daniel\bin)
133 13124 [main] ps 1296 mount_info::conv_to_posix_path: /home/daniel/bin = conv_to_posix_path (D:\cygwin64\home\daniel\bin)
150 13274 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\usr\local\bin, 0x10000100, no-add-slash)
123 13397 [main] ps 1296 normalize_win32_path: D:\cygwin64\usr\local\bin = normalize_win32_path (D:\cygwin64\usr\local\bin)
106 13503 [main] ps 1296 mount_info::conv_to_posix_path: /usr/local/bin = conv_to_posix_path (D:\cygwin64\usr\local\bin)
104 13607 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin, 0x10000100, no-add-slash)
105 13712 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin = normalize_win32_path (D:\cygwin64\bin)
105 13817 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (D:\cygwin64\bin)
100 13917 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin, 0x10000100, no-add-slash)
103 14020 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin = normalize_win32_path (D:\cygwin64\bin)
183 14203 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin = conv_to_posix_path (D:\cygwin64\bin)
108 14311 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin32\lib\gcc\i686-pc-cygwin\5.4.0, 0x10000100, no-add-slash)
102 14413 [main] ps 1296 normalize_win32_path: D:\cygwin32\lib\gcc\i686-pc-cygwin\5.4.0 = normalize_win32_path (D:\cygwin32\lib\gcc\i686-pc-cygwin\5.4.0)
100 14513 [main] ps 1296 mount_info::conv_to_posix_path: /d/cygwin32/lib/gcc/i686-pc-cygwin/5.4.0 = conv_to_posix_path (D:\cygwin32\lib\gcc\i686-pc-cygwin\5.4.0)
150 14663 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows\system32, 0x10000100, no-add-slash)
94 14757 [main] ps 1296 normalize_win32_path: C:\Windows\system32 = normalize_win32_path (C:\Windows\system32)
98 14855 [main] ps 1296 mount_info::conv_to_posix_path: /c/Windows/system32 = conv_to_posix_path (C:\Windows\system32)
93 14948 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows, 0x10000100, no-add-slash)
100 15048 [main] ps 1296 normalize_win32_path: C:\Windows = normalize_win32_path (C:\Windows)
105 15153 [main] ps 1296 mount_info::conv_to_posix_path: /c/Windows = conv_to_posix_path (C:\Windows)
93 15246 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows\System32\Wbem, 0x10000100, no-add-slash)
100 15346 [main] ps 1296 normalize_win32_path: C:\Windows\System32\Wbem = normalize_win32_path (C:\Windows\System32\Wbem)
97 15443 [main] ps 1296 mount_info::conv_to_posix_path: /c/Windows/System32/Wbem = conv_to_posix_path (C:\Windows\System32\Wbem)
92 15535 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Windows\System32\WindowsPowerShell\v1.0, 0x10000100, no-add-slash)
154 15689 [main] ps 1296 normalize_win32_path: C:\Windows\System32\WindowsPowerShell\v1.0 = normalize_win32_path (C:\Windows\System32\WindowsPowerShell\v1.0)
101 15790 [main] ps 1296 mount_info::conv_to_posix_path: /c/Windows/System32/WindowsPowerShell/v1.0 = conv_to_posix_path (C:\Windows\System32\WindowsPowerShell\v1.0)
94 15884 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit, 0x10000100, no-add-slash)
93 15977 [main] ps 1296 normalize_win32_path: C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit = normalize_win32_path (C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit)
94 16071 [main] ps 1296 mount_info::conv_to_posix_path: /c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit = conv_to_posix_path (C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit)
288 16359 [main] ps 1296 win_env::add_cache: posix /home/daniel/bin:/usr/local/bin:/usr/bin:/usr/bin:/d/cygwin32/lib/gcc/i686-pc-cygwin/5.4.0:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0:/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit
96 16455 [main] ps 1296 win_env::add_cache: native PATH=D:\cygwin64\home\daniel\bin;D:\cygwin64\usr\local\bin;D:\cygwin64\bin;D:\cygwin64\bin;D:\cygwin32\lib\gcc\i686-pc-cygwin\5.4.0;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files (x86)\Windows Kits\8.1\Windows Performance Toolkit
99 16554 [main] ps 1296 posify_maybe: env var converted to PATH=/home/daniel/bin:/usr/local/bin:/usr/bin:/usr/bin:/d/cygwin32/lib/gcc/i686-pc-cygwin/5.4.0:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0:/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit
317 16871 [main] ps 1296 win32env_to_cygenv: 0x600038E30: PATH=/home/daniel/bin:/usr/local/bin:/usr/bin:/usr/bin:/d/cygwin32/lib/gcc/i686-pc-cygwin/5.4.0:/c/Windows/system32:/c/Windows:/c/Windows/System32/Wbem:/c/Windows/System32/WindowsPowerShell/v1.0:/c/Program Files (x86)/Windows Kits/8.1/Windows Performance Toolkit
189 17060 [main] ps 1296 win32env_to_cygenv: 0x600028A90: PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC
196 17256 [main] ps 1296 win32env_to_cygenv: 0x600028AE0: PRINTER=Microsoft XPS Document Writer
184 17440 [main] ps 1296 win32env_to_cygenv: 0x600028B10: PROCESSOR_ARCHITECTURE=AMD64
182 17622 [main] ps 1296 win32env_to_cygenv: 0x600028B40: PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 42 Stepping 7, GenuineIntel
253 17875 [main] ps 1296 win32env_to_cygenv: 0x600028B90: PROCESSOR_LEVEL=6
185 18060 [main] ps 1296 win32env_to_cygenv: 0x600028BB0: PROCESSOR_REVISION=2a07
192 18252 [main] ps 1296 win32env_to_cygenv: 0x600038F40: PROFILEREAD=true
183 18435 [main] ps 1296 win32env_to_cygenv: 0x600038F60: PROGRAMFILES=C:\Program Files
183 18618 [main] ps 1296 win32env_to_cygenv: 0x600038F90: PS1=\e]0;\u@\h 64\a\[\e[01;34m\]${PWD}\n\[\e[01;32m\](\u@\h 64)\[\e[00;34m\]$\[\e[00m\]
201 18819 [main] ps 1296 win32env_to_cygenv: 0x600039000: PSModulePath=C:\Windows\system32\WindowsPowerShell\v1.0\Modules\
183 19002 [main] ps 1296 win32env_to_cygenv: 0x600039050: PUBLIC=C:\Users\Public
199 19201 [main] ps 1296 win32env_to_cygenv: 0x600039070: PWD=/home/daniel
182 19383 [main] ps 1296 win32env_to_cygenv: 0x600039090: ProgramData=C:\ProgramData
182 19565 [main] ps 1296 win32env_to_cygenv: 0x6000390C0: ProgramFiles(x86)=C:\Program Files (x86)
181 19746 [main] ps 1296 win32env_to_cygenv: 0x600039100: ProgramW6432=C:\Program Files
215 19961 [main] ps 1296 win32env_to_cygenv: 0x600039130: SHELL=/bin/bash
192 20153 [main] ps 1296 win32env_to_cygenv: 0x600039150: SHLVL=1
184 20337 [main] ps 1296 win32env_to_cygenv: 0x600039170: SSH_CLIENT=10.0.2.2 48916 22
183 20520 [main] ps 1296 win32env_to_cygenv: 0x6000391A0: SSH_CONNECTION=10.0.2.2 48916 10.0.2.15 22
180 20700 [main] ps 1296 win32env_to_cygenv: 0x6000391E0: SSH_TTY=/dev/pty1
211 20911 [main] ps 1296 win32env_to_cygenv: 0x600039200: SYSTEMDRIVE=C:
192 21103 [main] ps 1296 win32env_to_cygenv: 0x600039220: SYSTEMROOT=C:\Windows
185 21288 [main] ps 1296 getwinenv: can't set native for TEMP= since no environ yet
93 21381 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\tmp, 0x10000000, no-add-slash)
100 21481 [main] ps 1296 normalize_win32_path: D:\cygwin64\tmp = normalize_win32_path (D:\cygwin64\tmp)
94 21575 [main] ps 1296 mount_info::conv_to_posix_path: /tmp = conv_to_posix_path (D:\cygwin64\tmp)
275 21850 [main] ps 1296 win_env::add_cache: posix /tmp
85 21935 [main] ps 1296 win_env::add_cache: native TEMP=D:\cygwin64\tmp
95 22030 [main] ps 1296 posify_maybe: env var converted to TEMP=/tmp
309 22339 [main] ps 1296 win32env_to_cygenv: 0x6000392A0: TEMP=/tmp
185 22524 [main] ps 1296 win32env_to_cygenv: 0x600039240: TERM=xterm
181 22705 [main] ps 1296 getwinenv: can't set native for TMP= since no environ yet
92 22797 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\tmp, 0x10000000, no-add-slash)
128 22925 [main] ps 1296 normalize_win32_path: D:\cygwin64\tmp = normalize_win32_path (D:\cygwin64\tmp)
99 23024 [main] ps 1296 mount_info::conv_to_posix_path: /tmp = conv_to_posix_path (D:\cygwin64\tmp)
286 23310 [main] ps 1296 win_env::add_cache: posix /tmp
100 23410 [main] ps 1296 win_env::add_cache: native TMP=D:\cygwin64\tmp
100 23510 [main] ps 1296 posify_maybe: env var converted to TMP=/tmp
286 23796 [main] ps 1296 win32env_to_cygenv: 0x600039320: TMP=/tmp
205 24001 [main] ps 1296 win32env_to_cygenv: 0x6000392C0: TZ=America/Chicago
225 24226 [main] ps 1296 win32env_to_cygenv: 0x600039340: USER=daniel
184 24410 [main] ps 1296 win32env_to_cygenv: 0x600039360: USERDOMAIN=win7pro
184 24594 [main] ps 1296 win32env_to_cygenv: 0x600039380: USERNAME=daniel
181 24775 [main] ps 1296 win32env_to_cygenv: 0x6000393A0: USERPROFILE=C:\Users\daniel
181 24956 [main] ps 1296 win32env_to_cygenv: 0x6000393D0: VS100COMNTOOLS=C:\Program Files (x86)\Microsoft Visual Studio 10.0\Common7\Tools\
214 25170 [main] ps 1296 win32env_to_cygenv: 0x600039430: VS140COMNTOOLS=C:\Program Files (x86)\Microsoft Visual Studio 14.0\Common7\Tools\
208 25378 [main] ps 1296 win32env_to_cygenv: 0x600039490: VSSDK140Install=C:\Program Files (x86)\Microsoft Visual Studio 14.0\VSSDK\
169 25547 [main] ps 1296 win32env_to_cygenv: 0x6000394F0: WINDIR=C:\Windows
163 25710 [main] ps 1296 win32env_to_cygenv: 0x600039510: _=/usr/bin/strace
164 25874 [main] ps 1296 win32env_to_cygenv: 0x600039530: windows_tracing_flags=3
197 26071 [main] ps 1296 win32env_to_cygenv: 0x600039550: windows_tracing_logfile=C:\BVTBin\Tests\installpackage\csilogfile.log
103 26174 [main] ps 1296 pinfo_init: Set nice to 0
84 26258 [main] ps 1296 pinfo_init: pid 1296, pgid 1296, process_state 0x41
95 26353 [main] ps 1296 App version: 2008.0, api: 0.309
90 26443 [main] ps 1296 DLL version: 2008.1, api: 0.310
89 26532 [main] ps 1296 DLL build: 2017-04-15 14:47
96 26628 [main] ps 1296 dtable::extend: size 32, fds 0x180302E68
192 26820 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
804 27624 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
549 28173 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
493 28666 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
598 29264 [main] ps 1296 cygheap_user::ontherange: what 2, pw 0x180303088
98 29362 [main] ps 1296 cygheap_user::ontherange: HOME is already in the environment /home/daniel
256 29618 [main] ps 1296 build_argv: argv[0] = 'ps'
96 29714 [main] ps 1296 build_argv: argv[1] = '-ef'
85 29799 [main] ps 1296 build_argv: argc 2
292 30091 [main] ps 1296 build_fh_pc: created an archetype (0x1803040E8) for /dev/pty1(136/1)
128 30219 [main] ps 1296 build_fh_pc: fh 0x180303D78, dev 00880001
109 30328 [main] ps 1296 fhandler_pipe::create: name \\.\pipe\cygwin-f76db13c759b51fa-pty1-from-master, size 131072, mode PIPE_TYPE_MESSAGE
236 30564 [main] ps 1296 fhandler_pipe::create: pipe busy
89 30653 [main] ps 1296 tty::exists: exists 1
209 30862 [main] ps 1296 set_posix_access: ACL-Size: 124
165 31027 [main] ps 1296 set_posix_access: Created SD-Size: 200
99 31126 [main] ps 1296 fhandler_pty_slave::open: (393): pty output_mutex (0xCC): waiting -1 ms
69 31195 [main] ps 1296 fhandler_pty_slave::open: (393): pty output_mutex: acquired
130 31325 [main] ps 1296 tty::create_inuse: cygtty.slave_alive.1 0xD8
71 31396 [main] ps 1296 fhandler_pty_slave::open: (396): pty output_mutex(0xCC) released
138 31534 [main] ps 1296 open_shared: name cygpid.720, n 720, shared 0x30000 (wanted 0x0), h 0xDC, *m 6
77 31611 [main] ps 1296 fhandler_pty_slave::open: dup handles directly since I'm the owner
81 31692 [main] ps 1296 fhandler_pty_slave::open: duplicated from_master 0x1A4->0xDC from pty_owner
67 31759 [main] ps 1296 fhandler_pty_slave::open: duplicated to_master 0x1B4->0xE4 from pty_owner
65 31824 [main] ps 1296 fhandler_pty_slave::open: duplicated to_master_cyg 0x248->0xE8 from pty_owner
105 31929 [main] ps 1296 fhandler_console::need_invisible: invisible_console 0
72 32001 [main] ps 1296 fhandler_base::open_with_arch: line 453: /dev/pty1<0x1803040E8> usecount + 1 = 1
70 32071 [main] ps 1296 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
77 32148 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
66 32214 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
66 32280 [main] ps 1296 _pinfo::set_ctty: old no ctty, ctty device number 0xFFFFFFFF, tc.ntty device number 0x880001 flags & O_NOCTTY 0x0
60 32340 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty 0x0, archetype 0x1803040E8
64 32404 [main] ps 1296 _pinfo::set_ctty: ctty was NULL
64 32468 [main] ps 1296 _pinfo::set_ctty: line 479: /dev/pty1<0x1803040E8> usecount + 1 = 2
65 32533 [main] ps 1296 _pinfo::set_ctty: /dev/pty1 ctty, usecount 2
71 32604 [main] ps 1296 _pinfo::set_ctty: attaching ctty /dev/pty1 sid 1296, pid 1296, pgid 1296, tty->pgid 1576, tty->sid 340
68 32672 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty now 0x1803040E8, archetype 0x1803040E8
65 32737 [main] ps 1296 fhandler_pty_slave::open_setup: /dev/pty1 opened, usecount 2
66 32803 [main] ps 1296 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
65 32868 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
65 32933 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
65 32998 [main] ps 1296 _pinfo::set_ctty: old ctty /dev/pty1, ctty device number 0x880001, tc.ntty device number 0x880001 flags & O_NOCTTY 0x0
66 33064 [main] ps 1296 _pinfo::set_ctty: attaching ctty /dev/pty1 sid 340, pid 1296, pgid 1576, tty->pgid 1576, tty->sid 340
73 33137 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty now 0x1803040E8, archetype 0x1803040E8
65 33202 [main] ps 1296 fhandler_pty_slave::open_setup: /dev/pty1 opened, usecount 2
209 33411 [main] ps 1296 build_fh_pc: found an archetype for (null)(136/1) io_handle 0xDC
78 33489 [main] ps 1296 build_fh_pc: fh 0x1803044C8, dev 00880001
70 33559 [main] ps 1296 fhandler_base::open_with_arch: line 473: /dev/pty1<0x1803040E8> usecount + 1 = 3
65 33624 [main] ps 1296 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
65 33689 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
64 33753 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
66 33819 [main] ps 1296 _pinfo::set_ctty: old ctty /dev/pty1, ctty device number 0x880001, tc.ntty device number 0x880001 flags & O_NOCTTY 0x0
67 33886 [main] ps 1296 _pinfo::set_ctty: attaching ctty /dev/pty1 sid 340, pid 1296, pgid 1576, tty->pgid 1576, tty->sid 340
67 33953 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty now 0x1803040E8, archetype 0x1803040E8
65 34018 [main] ps 1296 fhandler_pty_slave::open_setup: /dev/pty1 opened, usecount 3
71 34089 [main] ps 1296 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
68 34157 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
65 34222 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
65 34287 [main] ps 1296 _pinfo::set_ctty: old ctty /dev/pty1, ctty device number 0x880001, tc.ntty device number 0x880001 flags & O_NOCTTY 0x0
124 34411 [main] ps 1296 _pinfo::set_ctty: attaching ctty /dev/pty1 sid 340, pid 1296, pgid 1576, tty->pgid 1576, tty->sid 340
67 34478 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty now 0x1803040E8, archetype 0x1803040E8
64 34542 [main] ps 1296 fhandler_pty_slave::open_setup: /dev/pty1 opened, usecount 3
209 34751 [main] ps 1296 build_fh_pc: found an archetype for (null)(136/1) io_handle 0xDC
74 34825 [main] ps 1296 build_fh_pc: fh 0x180304838, dev 00880001
69 34894 [main] ps 1296 fhandler_base::open_with_arch: line 473: /dev/pty1<0x1803040E8> usecount + 1 = 4
67 34961 [main] ps 1296 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
72 35033 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
72 35105 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
67 35172 [main] ps 1296 _pinfo::set_ctty: old ctty /dev/pty1, ctty device number 0x880001, tc.ntty device number 0x880001 flags & O_NOCTTY 0x0
68 35240 [main] ps 1296 _pinfo::set_ctty: attaching ctty /dev/pty1 sid 340, pid 1296, pgid 1576, tty->pgid 1576, tty->sid 340
65 35305 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty now 0x1803040E8, archetype 0x1803040E8
88 35393 [main] ps 1296 fhandler_pty_slave::open_setup: /dev/pty1 opened, usecount 4
64 35457 [main] ps 1296 fhandler_base::set_flags: flags 0x10002, supplied_bin 0x0
64 35521 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
64 35585 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
68 35653 [main] ps 1296 _pinfo::set_ctty: old ctty /dev/pty1, ctty device number 0x880001, tc.ntty device number 0x880001 flags & O_NOCTTY 0x0
69 35722 [main] ps 1296 _pinfo::set_ctty: attaching ctty /dev/pty1 sid 340, pid 1296, pgid 1576, tty->pgid 1576, tty->sid 340
66 35788 [main] ps 1296 _pinfo::set_ctty: cygheap->ctty now 0x1803040E8, archetype 0x1803040E8
65 35853 [main] ps 1296 fhandler_pty_slave::open_setup: /dev/pty1 opened, usecount 4
168 36021 [main] ps 1296 __set_errno: void dll_crt0_1(void*):979 setting errno 0
1126 37147 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
182 37329 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
290 37619 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
260 37879 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
254 38133 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
278 38411 [main] ps 1296 __get_lcid_from_locale: LCID=0x0409
441 38852 [main] ps 1296 time: 1492747214 = time(0x0)
197 39049 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
395 39444 [main] ps 1296 stat64: entering
118 39562 [main] ps 1296 normalize_posix_path: src /dev
78 39640 [main] ps 1296 normalize_posix_path: /dev = normalize_posix_path (/dev)
62 39702 [main] ps 1296 mount_info::conv_to_win32_path: conv_to_win32_path (/dev)
64 39766 [main] ps 1296 mount_info::cygdrive_win32_path: src '/dev', dst ''
65 39831 [main] ps 1296 set_flags: flags: binary (0x2)
63 39894 [main] ps 1296 mount_info::conv_to_win32_path: src_path /dev, dst D:\cygwin64\dev, flags 0x3000A, rc 0
92 39986 [main] ps 1296 symlink_info::check: 0x0 = NtCreateFile (\??\D:\cygwin64\dev)
92 40078 [main] ps 1296 symlink_info::check: not a symlink
68 40146 [main] ps 1296 symlink_info::check: 0 = symlink.check(D:\cygwin64\dev, 0xFFFF34F0) (0x43000A)
70 40216 [main] ps 1296 build_fh_pc: fh 0x180304C60, dev 000000C1
72 40288 [main] ps 1296 stat_worker: (\??\D:\cygwin64\dev, 0x1802DCA40, 0x180304C60), file_attributes 16
243 40531 [main] ps 1296 fhandler_base::fstat_helper: 0 = fstat (\??\D:\cygwin64\dev, 0x1802DCA40) st_size=0, st_mode=040755, st_ino=562949953421447st_atim=58F7D822.3084A780 st_ctim=58F7D822.3084A780 st_mtim=58F7D822.3084A780 st_birthtim=58D5D45B.9EE1D40
414 40945 [main] ps 1296 stat_worker: 0 = (\??\D:\cygwin64\dev,0x1802DCA40)
84 41029 [main] ps 1296 fstat64: 0 = fstat(1, 0xFFFF4820)
140 41169 [main] ps 1296 isatty: 1 = isatty(1)
251 41420 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 51)
63 41483 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
82 41565 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
67 41632 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
66 41698 [main] ps 1296 write: 51 = write(1, 0x60003A1B0, 51)
461 42159 [main] ps 1296 open_shared: name cygpid.720, n 720, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
195 42354 [main] ps 1296 open_shared: name cygpid.1728, n 1728, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
75 42429 [main] ps 1296 pinfo::init: execed process windows pid 1728, cygwin pid 720
73 42502 [main] ps 1296 open_shared: name cygpid.720, n 720, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
108 42610 [main] ps 1296 open_shared: name cygpid.984, n 984, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
187 42797 [main] ps 1296 open_shared: name cygpid.1144, n 1144, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
187 42984 [main] ps 1296 open_shared: name cygpid.1208, n 1208, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
73 43057 [main] ps 1296 pinfo::init: execed process windows pid 1208, cygwin pid 1176
85 43142 [main] ps 1296 open_shared: name cygpid.1176, n 1176, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
189 43331 [main] ps 1296 open_shared: name cygpid.340, n 340, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
186 43517 [main] ps 1296 open_shared: name cygpid.336, n 336, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
86 43603 [main] ps 1296 pinfo::init: execed process windows pid 336, cygwin pid 1020
76 43679 [main] ps 1296 open_shared: name cygpid.1020, n 1020, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
185 43864 [main] ps 1296 open_shared: name cygpid.1468, n 1468, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
195 44059 [main] ps 1296 open_shared: name cygpid.1852, n 1852, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
336 44395 [main] ps 1296 open_shared: name cygpid.1020, n 1020, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
118 44513 [main] ps 1296 open_shared: name cygpid.1176, n 1176, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
268 44781 [main] ps 1296 open_shared: name cygpid.360, n 360, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
126 44907 [main] ps 1296 pinfo::init: execed process windows pid 360, cygwin pid 1852
154 45061 [main] ps 1296 open_shared: name cygpid.1852, n 1852, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
147 45208 [main] ps 1296 open_shared: name cygpid.380, n 380, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
84 45292 [main] ps 1296 pinfo::init: execed process windows pid 380, cygwin pid 340
70 45362 [main] ps 1296 open_shared: name cygpid.340, n 340, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
77 45439 [main] ps 1296 open_shared: name cygpid.1044, n 1044, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
3119382 3164821 [main] ps 1296 open_shared: name cygpid.1576, n 1576, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
821 3165642 [main] ps 1296 open_shared: name cygpid.1420, n 1420, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
232 3165874 [main] ps 1296 pinfo::init: execed process windows pid 1420, cygwin pid 1468
196 3166070 [main] ps 1296 open_shared: name cygpid.1468, n 1468, shared 0x30000 (wanted 0x0), h 0xEC, *m 6
138 3166208 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\ps.exe, 0x0, no-add-slash)
219 3166427 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\ps.exe = normalize_win32_path (D:\cygwin64\bin\ps.exe)
79 3166506 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/ps.exe = conv_to_posix_path (D:\cygwin64\bin\ps.exe)
145 3166651 [main] ps 1296 time: 1492747217 = time(0x0)
255 3166906 [main] ps 1296 open: open(/usr/share/zoneinfo/America/Chicago, 0x10000)
73 3166979 [main] ps 1296 normalize_posix_path: src /usr/share/zoneinfo/America/Chicago
72 3167051 [main] ps 1296 normalize_posix_path: /usr/share/zoneinfo/America/Chicago = normalize_posix_path (/usr/share/zoneinfo/America/Chicago)
86 3167137 [main] ps 1296 mount_info::conv_to_win32_path: conv_to_win32_path (/usr/share/zoneinfo/America/Chicago)
75 3167212 [main] ps 1296 mount_info::cygdrive_win32_path: src '/usr/share/zoneinfo/America/Chicago', dst ''
71 3167283 [main] ps 1296 set_flags: flags: binary (0x2)
174 3167457 [main] ps 1296 mount_info::conv_to_win32_path: src_path /usr/share/zoneinfo/America/Chicago, dst D:\cygwin64\usr\share\zoneinfo\America\Chicago, flags 0x3000A, rc 0
132 3167589 [main] ps 1296 symlink_info::check: 0x0 = NtCreateFile (\??\D:\cygwin64\usr\share\zoneinfo\America\Chicago)
101 3167690 [main] ps 1296 symlink_info::check: not a symlink
106 3167796 [main] ps 1296 symlink_info::check: 0 = symlink.check(D:\cygwin64\usr\share\zoneinfo\America\Chicago, 0xFFFEEE10) (0x3000A)
83 3167879 [main] ps 1296 path_conv::check: this->path(D:\cygwin64\usr\share\zoneinfo\America\Chicago), has_acls(1)
85 3167964 [main] ps 1296 build_fh_pc: fh 0x180304C60, dev 000000C3
76 3168040 [main] ps 1296 fhandler_base::open: (\??\D:\cygwin64\usr\share\zoneinfo\America\Chicago, 0x118000)
107 3168147 [main] ps 1296 fhandler_base::set_flags: flags 0x118000, supplied_bin 0x10000
76 3168223 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
70 3168293 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
107 3168400 [main] ps 1296 fhandler_base::open: 0x0 = NtCreateFile (0xEC, 0x80100000, \??\D:\cygwin64\usr\share\zoneinfo\America\Chicago, io, NULL, 0x0, 0x7, 0x1, 0x4020, NULL, 0)
171 3168571 [main] ps 1296 fhandler_base::open: 1 = fhandler_base::open(\??\D:\cygwin64\usr\share\zoneinfo\America\Chicago, 0x118000)
79 3168650 [main] ps 1296 fhandler_base::open_fs: 1 = fhandler_disk_file::open(\??\D:\cygwin64\usr\share\zoneinfo\America\Chicago, 0x18000)
73 3168723 [main] ps 1296 open: 3 = open(/usr/share/zoneinfo/America/Chicago, 0x18000)
78 3168801 [main] ps 1296 read: read(3, 0x6000F0020, 41448) blocking
98 3168899 [main] ps 1296 fhandler_base::read: returning 3585, binary mode
84 3168983 [main] ps 1296 read: 3585 = read(3, 0x6000F0020, 3585)
71 3169054 [main] ps 1296 close: close(3)
87 3169141 [main] ps 1296 fhandler_base::close: closing '/usr/share/zoneinfo/America/Chicago' handle 0xEC
83 3169224 [main] ps 1296 close: 0 = close(3)
227 3169451 [main] ps 1296 open: open(/usr/share/zoneinfo/posixrules, 0x10000)
82 3169533 [main] ps 1296 normalize_posix_path: src /usr/share/zoneinfo/posixrules
71 3169604 [main] ps 1296 normalize_posix_path: /usr/share/zoneinfo/posixrules = normalize_posix_path (/usr/share/zoneinfo/posixrules)
70 3169674 [main] ps 1296 mount_info::conv_to_win32_path: conv_to_win32_path (/usr/share/zoneinfo/posixrules)
71 3169745 [main] ps 1296 mount_info::cygdrive_win32_path: src '/usr/share/zoneinfo/posixrules', dst ''
70 3169815 [main] ps 1296 set_flags: flags: binary (0x2)
71 3169886 [main] ps 1296 mount_info::conv_to_win32_path: src_path /usr/share/zoneinfo/posixrules, dst D:\cygwin64\usr\share\zoneinfo\posixrules, flags 0x3000A, rc 0
99 3169985 [main] ps 1296 symlink_info::check: 0x0 = NtCreateFile (\??\D:\cygwin64\usr\share\zoneinfo\posixrules)
96 3170081 [main] ps 1296 symlink_info::check: not a symlink
103 3170184 [main] ps 1296 symlink_info::check: 0 = symlink.check(D:\cygwin64\usr\share\zoneinfo\posixrules, 0xFFFEA4C0) (0x3000A)
83 3170267 [main] ps 1296 path_conv::check: this->path(D:\cygwin64\usr\share\zoneinfo\posixrules), has_acls(1)
75 3170342 [main] ps 1296 build_fh_pc: fh 0x180304C60, dev 000000C3
94 3170436 [main] ps 1296 fhandler_base::open: (\??\D:\cygwin64\usr\share\zoneinfo\posixrules, 0x118000)
120 3170556 [main] ps 1296 fhandler_base::set_flags: flags 0x118000, supplied_bin 0x10000
81 3170637 [main] ps 1296 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000
70 3170707 [main] ps 1296 fhandler_base::set_flags: filemode set to binary
70 3170777 [main] ps 1296 fhandler_base::open: 0x0 = NtCreateFile (0xEC, 0x80100000, \??\D:\cygwin64\usr\share\zoneinfo\posixrules, io, NULL, 0x0, 0x7, 0x1, 0x4020, NULL, 0)
72 3170849 [main] ps 1296 fhandler_base::open: 1 = fhandler_base::open(\??\D:\cygwin64\usr\share\zoneinfo\posixrules, 0x118000)
72 3170921 [main] ps 1296 fhandler_base::open_fs: 1 = fhandler_disk_file::open(\??\D:\cygwin64\usr\share\zoneinfo\posixrules, 0x18000)
72 3170993 [main] ps 1296 open: 3 = open(/usr/share/zoneinfo/posixrules, 0x18000)
71 3171064 [main] ps 1296 read: read(3, 0x6000FA210, 41448) blocking
99 3171163 [main] ps 1296 fhandler_base::read: returning 3545, binary mode
75 3171238 [main] ps 1296 read: 3545 = read(3, 0x6000FA210, 3545)
78 3171316 [main] ps 1296 close: close(3)
71 3171387 [main] ps 1296 fhandler_base::close: closing '/usr/share/zoneinfo/posixrules' handle 0xEC
93 3171480 [main] ps 1296 close: 0 = close(3)
689 3172169 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 55)
72 3172241 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
72 3172313 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
65 3172378 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
192 3172570 [main] ps 1296 write: 55 = write(1, 0x60003A1B0, 55)
353 3172923 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\usr\sbin\sshd.exe, 0x0, no-add-slash)
72 3172995 [main] ps 1296 normalize_win32_path: D:\cygwin64\usr\sbin\sshd.exe = normalize_win32_path (D:\cygwin64\usr\sbin\sshd.exe)
75 3173070 [main] ps 1296 mount_info::conv_to_posix_path: /usr/sbin/sshd.exe = conv_to_posix_path (D:\cygwin64\usr\sbin\sshd.exe)
154 3173224 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
469 3173693 [main] ps 1296 time: 1492747217 = time(0x0)
450 3174143 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 58)
75 3174218 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
73 3174291 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
72 3174363 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
75 3174438 [main] ps 1296 write: 58 = write(1, 0x60003A1B0, 58)
367 3174805 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\cygrunsrv.exe, 0x0, no-add-slash)
65 3174870 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\cygrunsrv.exe = normalize_win32_path (D:\cygwin64\bin\cygrunsrv.exe)
73 3174943 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/cygrunsrv.exe = conv_to_posix_path (D:\cygwin64\bin\cygrunsrv.exe)
146 3175089 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
336 3175425 [main] ps 1296 time: 1492747217 = time(0x0)
458 3175883 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 62)
70 3175953 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
70 3176023 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
75 3176098 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
73 3176171 [main] ps 1296 write: 62 = write(1, 0x60003A1B0, 62)
323 3176494 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\cygrunsrv.exe, 0x0, no-add-slash)
69 3176563 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\cygrunsrv.exe = normalize_win32_path (D:\cygwin64\bin\cygrunsrv.exe)
105 3176668 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/cygrunsrv.exe = conv_to_posix_path (D:\cygwin64\bin\cygrunsrv.exe)
86 3176754 [main] ps 1296 time: 1492747217 = time(0x0)
406 3177160 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 62)
68 3177228 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
69 3177297 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
69 3177366 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
70 3177436 [main] ps 1296 write: 62 = write(1, 0x60003A1B0, 62)
369 3177805 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\usr\sbin\sshd.exe, 0x0, no-add-slash)
69 3177874 [main] ps 1296 normalize_win32_path: D:\cygwin64\usr\sbin\sshd.exe = normalize_win32_path (D:\cygwin64\usr\sbin\sshd.exe)
69 3177943 [main] ps 1296 mount_info::conv_to_posix_path: /usr/sbin/sshd.exe = conv_to_posix_path (D:\cygwin64\usr\sbin\sshd.exe)
69 3178012 [main] ps 1296 time: 1492747217 = time(0x0)
404 3178416 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 58)
68 3178484 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
69 3178553 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
68 3178621 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
70 3178691 [main] ps 1296 write: 58 = write(1, 0x60003A1B0, 58)
370 3179061 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\bash.exe, 0x0, no-add-slash)
75 3179136 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\bash.exe = normalize_win32_path (D:\cygwin64\bin\bash.exe)
72 3179208 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/bash.exe = conv_to_posix_path (D:\cygwin64\bin\bash.exe)
72 3179280 [main] ps 1296 time: 1492747217 = time(0x0)
396 3179676 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 57)
76 3179752 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
116 3179868 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
101 3179969 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
77 3180046 [main] ps 1296 write: 57 = write(1, 0x60003A1B0, 57)
568 3180614 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\usr\sbin\cygserver.exe, 0x0, no-add-slash)
112 3180726 [main] ps 1296 normalize_win32_path: D:\cygwin64\usr\sbin\cygserver.exe = normalize_win32_path (D:\cygwin64\usr\sbin\cygserver.exe)
95 3180821 [main] ps 1296 mount_info::conv_to_posix_path: /usr/sbin/cygserver.exe = conv_to_posix_path (D:\cygwin64\usr\sbin\cygserver.exe)
84 3180905 [main] ps 1296 time: 1492747217 = time(0x0)
423 3181328 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 63)
70 3181398 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
69 3181467 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
69 3181536 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
71 3181607 [main] ps 1296 write: 63 = write(1, 0x60003A1B0, 63)
365 3181972 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\bash.exe, 0x0, no-add-slash)
69 3182041 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\bash.exe = normalize_win32_path (D:\cygwin64\bin\bash.exe)
76 3182117 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/bash.exe = conv_to_posix_path (D:\cygwin64\bin\bash.exe)
71 3182188 [main] ps 1296 time: 1492747217 = time(0x0)
422 3182610 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 57)
69 3182679 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
69 3182748 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
68 3182816 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
92 3182908 [main] ps 1296 write: 57 = write(1, 0x60003A1B0, 57)
345 3183253 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\usr\sbin\sshd.exe, 0x0, no-add-slash)
70 3183323 [main] ps 1296 normalize_win32_path: D:\cygwin64\usr\sbin\sshd.exe = normalize_win32_path (D:\cygwin64\usr\sbin\sshd.exe)
68 3183391 [main] ps 1296 mount_info::conv_to_posix_path: /usr/sbin/sshd.exe = conv_to_posix_path (D:\cygwin64\usr\sbin\sshd.exe)
71 3183462 [main] ps 1296 time: 1492747217 = time(0x0)
412 3183874 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 58)
98 3183972 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
70 3184042 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
79 3184121 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
72 3184193 [main] ps 1296 write: 58 = write(1, 0x60003A1B0, 58)
336 3184529 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\strace.exe, 0x0, no-add-slash)
69 3184598 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\strace.exe = normalize_win32_path (D:\cygwin64\bin\strace.exe)
68 3184666 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/strace.exe = conv_to_posix_path (D:\cygwin64\bin\strace.exe)
139 3184805 [main] ps 1296 transport_layer_pipes::connect: Try to connect to named pipe: \\.\pipe\cygwin-f76db13c759b51fa-lpc
--- Process 1296 thread 1548 created
5307 3190112 [main] ps 1296 pwdgrp::fetch_account_from_windows: LookupAccountSidW (S-1-5-0), Win32 error 1332
161 3190273 [main] ps 1296 time: 1492747217 = time(0x0)
606 3190879 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 58)
87 3190966 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
79 3191045 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
157 3191202 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
114 3191316 [main] ps 1296 write: 58 = write(1, 0x60003A1B0, 58)
379 3191695 [main] ps 1296 mount_info::conv_to_posix_path: conv_to_posix_path (D:\cygwin64\bin\strace.exe, 0x0, no-add-slash)
81 3191776 [main] ps 1296 normalize_win32_path: D:\cygwin64\bin\strace.exe = normalize_win32_path (D:\cygwin64\bin\strace.exe)
80 3191856 [main] ps 1296 mount_info::conv_to_posix_path: /usr/bin/strace.exe = conv_to_posix_path (D:\cygwin64\bin\strace.exe)
82 3191938 [main] ps 1296 time: 1492747217 = time(0x0)
518 3192456 [main] ps 1296 fhandler_pty_slave::write: pty1, write(0x60003A1B0, 59)
74 3192530 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex (0xCC): waiting -1 ms
75 3192605 [main] ps 1296 fhandler_pty_common::process_opost_output: (1902): pty output_mutex: acquired
74 3192679 [main] ps 1296 fhandler_pty_common::process_opost_output: (1941): pty output_mutex(0xCC) released
76 3192755 [main] ps 1296 write: 59 = write(1, 0x60003A1B0, 59)
1448 3194203 [main] ps 1296 do_exit: do_exit (0), exit_state 1
170 3194373 [main] ps 1296 void: 0x0 = signal (20, 0x1)
75 3194448 [main] ps 1296 void: 0x0 = signal (1, 0x1)
74 3194522 [main] ps 1296 void: 0x0 = signal (2, 0x1)
72 3194594 [main] ps 1296 void: 0x0 = signal (3, 0x1)
76 3194670 [main] ps 1296 fhandler_base::close_with_arch: line 1120: /dev/pty1<0x1803040E8> usecount + -1 = 3
73 3194743 [main] ps 1296 fhandler_base::close_with_arch: not closing archetype
74 3194817 [main] ps 1296 fhandler_base::close_with_arch: line 1120: /dev/pty1<0x1803040E8> usecount + -1 = 2
73 3194890 [main] ps 1296 fhandler_base::close_with_arch: not closing archetype
76 3194966 [main] ps 1296 fhandler_base::close_with_arch: line 1120: /dev/pty1<0x1803040E8> usecount + -1 = 1
73 3195039 [main] ps 1296 fhandler_base::close_with_arch: not closing archetype
179 3195218 [main] ps 1296 init_cygheap::close_ctty: closing cygheap->ctty 0x1803040E8
84 3195302 [main] ps 1296 fhandler_base::close_with_arch: closing passed in archetype 0x0, usecount 0
73 3195375 [main] ps 1296 fhandler_pty_slave::cleanup: /dev/pty1 closed, usecount 0
91 3195466 [main] ps 1296 fhandler_pty_slave::close: closing last open /dev/pty1 handle
240 3195706 [main] ps 1296 fhandler_console::free_console: freed console, res 1
99 3195805 [main] ps 1296 fhandler_pty_common::close: pty1 <0xDC,0xE4> closing
161 3195966 [main] ps 1296 dtable::delete_archetype: deleting element 0 for /dev/pty1(136/1)
90 3196056 [main] ps 1296 getpid: 1296 = getpid()
119 3196175 [main] ps 1296 proc_terminate: nprocs 0
177 3196352 [main] ps 1296 proc_terminate: leaving
100 3196452 [main] ps 1296 pinfo::exit: Calling ExitProcess n 0x0, exitcode 0x0
--- Process 1296 thread 1080 exited with status 0x0
--- Process 1296 thread 1548 exited with status 0x0
--- Process 1296 exited with status 0x0
[-- Attachment #3: Type: text/plain, Size: 219 bytes --]
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-21 9:38 ` Daniel Santos
@ 2017-04-21 11:06 ` Daniel Santos
2017-04-21 12:08 ` Mark Geisert
0 siblings, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-21 11:06 UTC (permalink / raw)
To: cygwin
I've tracked it down to this little Sleep() loop in pinfo::init.
bool created = shloc != SH_JUSTOPEN;
/* Detect situation where a transitional memory block is being
retrieved.
If the block has been allocated with PINFO_REDIR_SIZE but not yet
updated with a PID_EXECED state then we'll retry. */
if (!created && !(flag & PID_NEW))
/* If not populated, wait 2 seconds for procinfo to become populated.
Would like to wait with finer granularity but that is not easily
doable. */
for (int i = 0; i < 200 && !procinfo->ppid; i++)
Sleep (10);
I tried putting a stupid memory barrier in the loop and a volatile read
just for kicks, but that doesn't seem to be the problem. I'm headed off
to bed. This only happens when using strace, so if anybody has ideas
please post.
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-21 11:06 ` Daniel Santos
@ 2017-04-21 12:08 ` Mark Geisert
2017-04-21 18:23 ` Daniel Santos
0 siblings, 1 reply; 15+ messages in thread
From: Mark Geisert @ 2017-04-21 12:08 UTC (permalink / raw)
To: cygwin
Daniel Santos wrote:
> I've tracked it down to this little Sleep() loop in pinfo::init.
>
> bool created = shloc != SH_JUSTOPEN;
>
> /* Detect situation where a transitional memory block is being retrieved.
> If the block has been allocated with PINFO_REDIR_SIZE but not yet
> updated with a PID_EXECED state then we'll retry. */
> if (!created && !(flag & PID_NEW))
> /* If not populated, wait 2 seconds for procinfo to become populated.
> Would like to wait with finer granularity but that is not easily
> doable. */
> for (int i = 0; i < 200 && !procinfo->ppid; i++)
> Sleep (10);
>
> I tried putting a stupid memory barrier in the loop and a volatile read just for
> kicks, but that doesn't seem to be the problem. I'm headed off to bed. This
> only happens when using strace, so if anybody has ideas please post.
I can reproduce your issue on a real Win7.64 machine so that removes any
possible virtual machine root cause. I was running 'top -s1' in one window
while running your testcase in another window. Yes, top froze for many seconds
at a time, then caught its display up, only to freeze again repeatedly. It was
still frozen for a while after your testcase had ended (!), then caught up.
Your mention of pinfo::init and 'ps' along with my usage of 'top' leads me to
think this may be somehow related to the /proc filesystem.
Here's my humble contribution to the discussion:
~ time w
02:15:52 up 3 days, 20:34, 0 users, load average: 0.99, 0.62, 0.31
USER TTY LOGIN@ IDLE JCPU PCPU WHAT
real 0m0.203s <-- OK, nice and fast
user 0m0.077s
sys 0m0.139s
~ time strace -o w.out w
02:16:23 up 3 days, 20:34, 0 users, load average: 0.54, 0.55, 0.29
USER TTY LOGIN@ IDLE JCPU PCPU WHAT
real 0m28.487s <-- but stracing it is much, much slower
user 0m0.015s
sys 0m0.000s
The 'w' command is normally pretty fast. Running it under strace makes it take
an unreasonably long time. Something seems busted somewhere. The strace output
for this example has many occurrences of ~3.1-second delays that seem to occur
as w is accumulating process time information for all processes.
..mark
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-21 12:08 ` Mark Geisert
@ 2017-04-21 18:23 ` Daniel Santos
2017-04-22 15:24 ` Mark Geisert
0 siblings, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-21 18:23 UTC (permalink / raw)
To: cygwin
On 04/21/2017 04:38 AM, Mark Geisert wrote:
>
> I can reproduce your issue on a real Win7.64 machine so that removes
> any possible virtual machine root cause. I was running 'top -s1' in
> one window while running your testcase in another window. Yes, top
> froze for many seconds at a time, then caught its display up, only to
> freeze again repeatedly. It was still frozen for a while after your
> testcase had ended (!), then caught up. Your mention of pinfo::init
> and 'ps' along with my usage of 'top' leads me to think this may be
> somehow related to the /proc filesystem.
>
> Here's my humble contribution to the discussion:
>
> ~ time w
> 02:15:52 up 3 days, 20:34, 0 users, load average: 0.99, 0.62, 0.31
> USER TTY LOGIN@ IDLE JCPU PCPU WHAT
>
> real 0m0.203s <-- OK, nice and fast
> user 0m0.077s
> sys 0m0.139s
>
> ~ time strace -o w.out w
> 02:16:23 up 3 days, 20:34, 0 users, load average: 0.54, 0.55, 0.29
> USER TTY LOGIN@ IDLE JCPU PCPU WHAT
>
> real 0m28.487s <-- but stracing it is much, much slower
> user 0m0.015s
> sys 0m0.000s
>
> The 'w' command is normally pretty fast. Running it under strace
> makes it take an unreasonably long time. Something seems busted
> somewhere. The strace output for this example has many occurrences of
> ~3.1-second delays that seem to occur as w is accumulating process
> time information for all processes.
>
> ..mark
Thanks for the help Mark. My current suspicion is that the _pinfo isn't
getting initialized when the process is exec-ed by strace, but I haven't
proved that. I added a dump() member function to _pinfo, but it crashes
and I can't seem to debug that in gdb (it makes a stacktrace file
instead of letting me debug). So the cygpid.<n> shared object is there,
but I'm suspecting that it's either all zeros or just not fully
initialized -- and this is for the pid of the strace process. So for
each strace process, there's a 2-3 second delay when trying to read the
process list.
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-21 18:23 ` Daniel Santos
@ 2017-04-22 15:24 ` Mark Geisert
2017-04-23 12:58 ` Daniel Santos
0 siblings, 1 reply; 15+ messages in thread
From: Mark Geisert @ 2017-04-22 15:24 UTC (permalink / raw)
To: cygwin
Daniel Santos wrote:
> Thanks for the help Mark. My current suspicion is that the _pinfo isn't getting
> initialized when the process is exec-ed by strace, but I haven't proved that. I
> added a dump() member function to _pinfo, but it crashes and I can't seem to
> debug that in gdb (it makes a stacktrace file instead of letting me debug). So
> the cygpid.<n> shared object is there, but I'm suspecting that it's either all
> zeros or just not fully initialized -- and this is for the pid of the strace
> process. So for each strace process, there's a 2-3 second delay when trying to
> read the process list.
Re debugging strace itself, you may not realize that strace is not a
Cygwin-native program. It's a Windows-native program. So debugging it with
Cygwin gdb is problematic.
I can tell you roughly how strace operates. It launches the target program with
CreateProcess(), not with exec(). It acts as the debugger of the target in
order to receive Windows DEBUG_EVENTs for things like DLL loads, thread
creation, etc. etc. The Cygwin DLL in the target can tell when it's being run
under strace and generates trace lines with OutputDebugString() calls that
strace receives as DEBUG_EVENTs. strace then just outputs the trace line.
strace does have to explicitly ContinueDebugEvent() on each DEBUG_EVENT it
receives, and if there's some issue with that then the target program will
remain suspended awaiting that continue. I've never seen an issue with this but
it's another possible place to look, I suppose.
Why strace appears to interact badly with /proc accesses, I have no idea.
..mark
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-22 15:24 ` Mark Geisert
@ 2017-04-23 12:58 ` Daniel Santos
2017-04-23 18:15 ` Mark Geisert
0 siblings, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-23 12:58 UTC (permalink / raw)
To: cygwin
On 04/21/2017 05:12 PM, Mark Geisert wrote:
>
> Re debugging strace itself, you may not realize that strace is not a
> Cygwin-native program. It's a Windows-native program. So debugging
> it with Cygwin gdb is problematic.
>
> I can tell you roughly how strace operates. It launches the target
> program with CreateProcess(), not with exec(). It acts as the
> debugger of the target in order to receive Windows DEBUG_EVENTs for
> things like DLL loads, thread creation, etc. etc. The Cygwin DLL in
> the target can tell when it's being run under strace and generates
> trace lines with OutputDebugString() calls that strace receives as
> DEBUG_EVENTs. strace then just outputs the trace line.
>
> strace does have to explicitly ContinueDebugEvent() on each
> DEBUG_EVENT it receives, and if there's some issue with that then the
> target program will remain suspended awaiting that continue. I've
> never seen an issue with this but it's another possible place to look,
> I suppose.
>
> Why strace appears to interact badly with /proc accesses, I have no idea.
>
> ..mark
Well thank you, I wish I had read this earlier. I've been trying to
debug (with gdb) strace (following children) and now I know why the
debugger is blowing through breakpoints, because I may be debugging
strace, but strace debugging it's own child. I added a _pinfo::dump ()
member function that I'm calling from pinfo::init () after the test "if
(!created && !(flag & PID_NEW))" and it's crashing because for some
processes, the entire _pinfo struct isn't mapped in, just the first
page. Of course, I'm a newbie in this sphere, so maybe I've missed
something and there's sometimes a reason for this? (The first part of
the struct looks normal.) Otherwise, that would be another odd flaw.
Anyway, I can see that the strace process's shared _pinfo object is
never fully populated:
_pinfo 0x30000 {
pid 2800,
process_state 0x00000001,
ppid 0,
exitcode 0
cygstarted 0,
dwProcessId 0x00000AF0,
progname "D:\cygwin64\bin\strace.exe",
uid 0,
gid 0,
pgid 0,
sid 0,
ctty 0,
has_pgid_children 0
start_time 1492881370,
nice 0,
stopsig 0,
sendsig 0x0,
exec_sendsig 0x0,
exec_dwProcessId 0
}
So I would venture to say that is a problem. Also, pinfo::init() should
probably issure some error message if it waits 2-ish seconds and the
struct still isn't correctly populated.
Is there a way to debug the children of strace? It would make it a lot
easier. That's part of why I wrote the _pinfo::debug(), but also when I
debug strace with gdb, the _pinfo struct IS properly populated. The
best problems are the ones that disappear when you try to debug them.
Thanks,
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-23 12:58 ` Daniel Santos
@ 2017-04-23 18:15 ` Mark Geisert
2017-04-24 8:23 ` Daniel Santos
2017-04-24 9:24 ` Daniel Santos
0 siblings, 2 replies; 15+ messages in thread
From: Mark Geisert @ 2017-04-23 18:15 UTC (permalink / raw)
To: cygwin
Daniel Santos wrote:
>
> On 04/21/2017 05:12 PM, Mark Geisert wrote:
>>
>> Re debugging strace itself, you may not realize that strace is not a
>> Cygwin-native program. It's a Windows-native program. So debugging it with
>> Cygwin gdb is problematic.
>>
>> I can tell you roughly how strace operates. It launches the target program
>> with CreateProcess(), not with exec(). It acts as the debugger of the target
>> in order to receive Windows DEBUG_EVENTs for things like DLL loads, thread
>> creation, etc. etc. The Cygwin DLL in the target can tell when it's being run
>> under strace and generates trace lines with OutputDebugString() calls that
>> strace receives as DEBUG_EVENTs. strace then just outputs the trace line.
>>
>> strace does have to explicitly ContinueDebugEvent() on each DEBUG_EVENT it
>> receives, and if there's some issue with that then the target program will
>> remain suspended awaiting that continue. I've never seen an issue with this
>> but it's another possible place to look, I suppose.
>>
>> Why strace appears to interact badly with /proc accesses, I have no idea.
>>
>> ..mark
>
> Well thank you, I wish I had read this earlier. I've been trying to debug (with
> gdb) strace (following children) and now I know why the debugger is blowing
> through breakpoints, because I may be debugging strace, but strace debugging
> it's own child. I added a _pinfo::dump () member function that I'm calling from
> pinfo::init () after the test "if (!created && !(flag & PID_NEW))" and it's
> crashing because for some processes, the entire _pinfo struct isn't mapped in,
> just the first page. Of course, I'm a newbie in this sphere, so maybe I've
> missed something and there's sometimes a reason for this? (The first part of
> the struct looks normal.) Otherwise, that would be another odd flaw.
I don't know enough about pinfo.h and pinfo.cc to say anything definite on this.
> Anyway, I can see that the strace process's shared _pinfo object is never fully
> populated:
>
> _pinfo 0x30000 {
> pid 2800,
> process_state 0x00000001,
> ppid 0,
> exitcode 0
> cygstarted 0,
> dwProcessId 0x00000AF0,
> progname "D:\cygwin64\bin\strace.exe",
> uid 0,
> gid 0,
> pgid 0,
> sid 0,
> ctty 0,
> has_pgid_children 0
> start_time 1492881370,
> nice 0,
> stopsig 0,
> sendsig 0x0,
> exec_sendsig 0x0,
> exec_dwProcessId 0
> }
Again, strace.exe is a Windows executable, so perhaps some of those fields don't
make sense for a non-Cygwin process and are not initialized? Purely speculation
on my part.
> So I would venture to say that is a problem. Also, pinfo::init() should
> probably issure some error message if it waits 2-ish seconds and the struct
> still isn't correctly populated.
That seems right. I unfortunately don't know why the code presumes the struct
is always populated within a certain (small) amount of time. The complaint
comment about minimum possible sleep duration sure makes it seem like it's
always supposed to be populated very quickly.
> Is there a way to debug the children of strace? It would make it a lot easier.
> That's part of why I wrote the _pinfo::debug(), but also when I debug strace
> with gdb, the _pinfo struct IS properly populated. The best problems are the
> ones that disappear when you try to debug them.
strace always acts as the debugger of the target process you start strace with
(or attach to; see '-p' in strace's help). strace has a switch '-f' ==
'--trace-children' that defaults to being ON. So by default strace is getting
DEBUG_EVENTs from the target strace launched as well as any process the target
creates.
If you explicitly set the '-f' flag, you're actually turning OFF that default
and *only* the target process sends DEBUG_EVENTs. In that case any process the
target creates will be invisible to strace. You could conceivably debug those
sub-processes with gdb but you likely won't be able to catch them at their
startup unless they wait for your attach.
..mark
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-23 18:15 ` Mark Geisert
@ 2017-04-24 8:23 ` Daniel Santos
2017-04-24 9:24 ` Daniel Santos
1 sibling, 0 replies; 15+ messages in thread
From: Daniel Santos @ 2017-04-24 8:23 UTC (permalink / raw)
To: cygwin
Unfortunately, I don't have much time to spend on this issue as the gcc8
stage1 has started and I have a few more issues to clear up with my
patchset.
On 04/23/2017 02:42 AM, Mark Geisert wrote:
>> Anyway, I can see that the strace process's shared _pinfo object is
>> never fully
>> populated:
>>
>> _pinfo 0x30000 {
>> pid 2800,
>> process_state 0x00000001,
>> ppid 0,
>> exitcode 0
>> cygstarted 0,
>> dwProcessId 0x00000AF0,
>> progname "D:\cygwin64\bin\strace.exe",
>> uid 0,
>> gid 0,
>> pgid 0,
>> sid 0,
>> ctty 0,
>> has_pgid_children 0
>> start_time 1492881370,
>> nice 0,
>> stopsig 0,
>> sendsig 0x0,
>> exec_sendsig 0x0,
>> exec_dwProcessId 0
>> }
>
> Again, strace.exe is a Windows executable, so perhaps some of those
> fields don't make sense for a non-Cygwin process and are not
> initialized? Purely speculation on my part.
Oh, I understand now, thanks. :) So it doesn't link to cygwin1.dll (or
any other cygwin libs), that makes sense. So the flaw is probably
thinking that this executable *should* have uid, guid, ppid, etc. Yet,
it exists in the cygwin process database (apparently a bunch of shared
(probably anonymous) files?). So the mistake is either listing it in
the database or not accounting for the possibility of strace, the
semi-cygwin program? Maybe there should be (or is?) a flag to tell
readers of the cygwin process database that this is a "special case"
process?
>> So I would venture to say that is a problem. Also, pinfo::init() should
>> probably issure some error message if it waits 2-ish seconds and the
>> struct
>> still isn't correctly populated.
>
> That seems right. I unfortunately don't know why the code presumes
> the struct is always populated within a certain (small) amount of
> time. The complaint comment about minimum possible sleep duration
> sure makes it seem like it's always supposed to be populated very
> quickly.
>
Yes, and not knowing cygwin's architecture it's hard for me to guess
why, although I can do a git blame and try to understand when the code
was put in. Also, anything like this usually screams race condition in
my ear, but I can't say that w/o really understanding it well and what
assumptions are being made. For instance, if another thread/process
could really modify this then reads should be done using known atomic
instructions. On 32-bit x86, iirc, a mov of the machine word size is
always atomic, i.e., either you get an intact old value or you get an
intact new value, you should never get two bytes of the new value and
two bytes of the old. But when I'm writing C code, I never want to
presume what the compiler will emit for situations like this and it's
better to use some atomic read/write macro/inline, even though I can't
really imagine this particular snippet not using a simple mov, using an
explicit "atomic" function/macro conveys the intention.
I should note that in the case of trying to analyze this problem with
expect, I allowed a make -kj8 check to run for a few days (should take
maybe 4 hours) and I never had the race condition. Presumably, if I
allowed it to run for a very long period or time (months or years) it
would have likely occurred.
>> Is there a way to debug the children of strace? It would make it a
>> lot easier.
>> That's part of why I wrote the _pinfo::debug(), but also when I debug
>> strace
>> with gdb, the _pinfo struct IS properly populated. The best problems
>> are the
>> ones that disappear when you try to debug them.
>
> strace always acts as the debugger of the target process you start
> strace with (or attach to; see '-p' in strace's help). strace has a
> switch '-f' == '--trace-children' that defaults to being ON. So by
> default strace is getting DEBUG_EVENTs from the target strace launched
> as well as any process the target creates.
>
> If you explicitly set the '-f' flag, you're actually turning OFF that
> default and *only* the target process sends DEBUG_EVENTs. In that
> case any process the target creates will be invisible to strace. You
> could conceivably debug those sub-processes with gdb but you likely
> won't be able to catch them at their startup unless they wait for your
> attach.
>
Very interesting! Is it possible to have two processes debugging and
have strace forward debug events that it isn't interested in to another
debugger in the chain? I'm probably just talking crazy here. Either
way, that's ancillary to fixing the problem.
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-23 18:15 ` Mark Geisert
2017-04-24 8:23 ` Daniel Santos
@ 2017-04-24 9:24 ` Daniel Santos
2017-04-24 9:34 ` Mark Geisert
1 sibling, 1 reply; 15+ messages in thread
From: Daniel Santos @ 2017-04-24 9:24 UTC (permalink / raw)
To: cygwin
Well, waiting for GNU/Linux tests to run, so I had a little more time to
play with this.
On 04/23/2017 02:42 AM, Mark Geisert wrote:
> Daniel Santos wrote:
>> Well thank you, I wish I had read this earlier. I've been trying to
>> debug (with
>> gdb) strace (following children) and now I know why the debugger is
>> blowing
>> through breakpoints, because I may be debugging strace, but strace
>> debugging
>> it's own child. I added a _pinfo::dump () member function that I'm
>> calling from
>> pinfo::init () after the test "if (!created && !(flag & PID_NEW))"
>> and it's
>> crashing because for some processes, the entire _pinfo struct isn't
>> mapped in,
>> just the first page. Of course, I'm a newbie in this sphere, so
>> maybe I've
>> missed something and there's sometimes a reason for this? (The first
>> part of
>> the struct looks normal.) Otherwise, that would be another odd flaw.
>
> I don't know enough about pinfo.h and pinfo.cc to say anything
> definite on this.
Well here's one mystery solved. I modified my dump() function to first
dump the first page of the struct and then the second, so that when it
crashes I can see the contents of the first page at least:
_pinfo 0x30000 {
pid 2044,
process_state 0x00004001,
ppid 2044,
exitcode 0
cygstarted 0,
dwProcessId 0x00000000,
progname "",
The process_state's bit 0x00004000 happens to be PID_EXECED, so this is
intentionally shorter because there's no more information.
As for the strange _pinfo object that causes the delay, this appears to
be an error in the process database because the windows PID is a
duplicate of another process entry. (I modified ps.exe to output the
_pinfo::process_state field.)
$ strace --trace-children --output=/tmp/ps.log --mask=all ps -el
PID PPID PGID WINPID TTY UID STIME STATE
COMMAND
948 1788 948 1772 pty0 197608 00:04:22
000000c1 /usr/bin/bash
2720 1 2720 2720 ? 18 00:02:42
00000041 /usr/bin/cygrunsrv
860 0 0 860 pty0 0 00:04:30
00000001 /usr/bin/cygrunsrv
984 1 2168 984 pty0 197608 00:04:30
00000041 /usr/bin/ps
2376 1628 2376 2612 ? 197610 00:02:45
000000c1 /usr/sbin/sshd
2524 2720 2524 1404 ? 18 00:02:42
000000c1 /usr/sbin/cygserver
2168 948 2168 860 pty0 197608 00:04:30
00000061 /usr/bin/strace
1788 2376 1788 2788 ? 197610 00:04:22
000000c1 /usr/sbin/sshd
1628 1 1628 1628 ? 197610 00:02:45
00000041 /usr/bin/cygrunsrv
The entry that causes the delay is the one with a zero PPID and PGID and
the progname field is wrong -- It isn't "cygrunsrv". It always has the
same progname name of the previous process. Notice that the WINPID
field has the same value as the PID of the strace process that's real
(2168).
So my guess is that this object shouldn't even be there.
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-24 9:24 ` Daniel Santos
@ 2017-04-24 9:34 ` Mark Geisert
2017-04-24 15:00 ` Daniel Santos
2017-04-24 19:30 ` Daniel Santos
0 siblings, 2 replies; 15+ messages in thread
From: Mark Geisert @ 2017-04-24 9:34 UTC (permalink / raw)
To: cygwin
Daniel Santos wrote:
> Well, waiting for GNU/Linux tests to run, so I had a little more time to play
> with this.
>
> On 04/23/2017 02:42 AM, Mark Geisert wrote:
>> Daniel Santos wrote:
>>> Well thank you, I wish I had read this earlier. I've been trying to debug (with
>>> gdb) strace (following children) and now I know why the debugger is blowing
>>> through breakpoints, because I may be debugging strace, but strace debugging
>>> it's own child. I added a _pinfo::dump () member function that I'm calling from
>>> pinfo::init () after the test "if (!created && !(flag & PID_NEW))" and it's
>>> crashing because for some processes, the entire _pinfo struct isn't mapped in,
>>> just the first page. Of course, I'm a newbie in this sphere, so maybe I've
>>> missed something and there's sometimes a reason for this? (The first part of
>>> the struct looks normal.) Otherwise, that would be another odd flaw.
>>
>> I don't know enough about pinfo.h and pinfo.cc to say anything definite on this.
>
> Well here's one mystery solved. I modified my dump() function to first dump the
> first page of the struct and then the second, so that when it crashes I can see
> the contents of the first page at least:
>
> _pinfo 0x30000 {
> pid 2044,
> process_state 0x00004001,
> ppid 2044,
> exitcode 0
> cygstarted 0,
> dwProcessId 0x00000000,
> progname "",
>
> The process_state's bit 0x00004000 happens to be PID_EXECED, so this is
> intentionally shorter because there's no more information.
>
> As for the strange _pinfo object that causes the delay, this appears to be an
> error in the process database because the windows PID is a duplicate of another
> process entry. (I modified ps.exe to output the _pinfo::process_state field.)
>
> $ strace --trace-children --output=/tmp/ps.log --mask=all ps -el
> PID PPID PGID WINPID TTY UID STIME STATE COMMAND
> 948 1788 948 1772 pty0 197608 00:04:22 000000c1
> /usr/bin/bash
> 2720 1 2720 2720 ? 18 00:02:42 00000041
> /usr/bin/cygrunsrv
> 860 0 0 860 pty0 0 00:04:30 00000001
> /usr/bin/cygrunsrv
> 984 1 2168 984 pty0 197608 00:04:30 00000041
> /usr/bin/ps
> 2376 1628 2376 2612 ? 197610 00:02:45 000000c1
> /usr/sbin/sshd
> 2524 2720 2524 1404 ? 18 00:02:42 000000c1
> /usr/sbin/cygserver
> 2168 948 2168 860 pty0 197608 00:04:30 00000061
> /usr/bin/strace
> 1788 2376 1788 2788 ? 197610 00:04:22 000000c1
> /usr/sbin/sshd
> 1628 1 1628 1628 ? 197610 00:02:45 00000041
> /usr/bin/cygrunsrv
>
> The entry that causes the delay is the one with a zero PPID and PGID and the
> progname field is wrong -- It isn't "cygrunsrv". It always has the same
> progname name of the previous process. Notice that the WINPID field has the
> same value as the PID of the strace process that's real (2168).
>
> So my guess is that this object shouldn't even be there.
Excellent debugging work! I'm inclined to agree with your last point. I'm
poring over pinfo.cc as well as dcrt0.cc, which is the Cygwin DLL init code.
The latter talks about special cases if the DLL is runtime loaded (like strace
does) vs link-time loaded (like Cygwin apps do). May take me a while to respond.
..mark
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-24 9:34 ` Mark Geisert
@ 2017-04-24 15:00 ` Daniel Santos
2017-04-24 19:30 ` Daniel Santos
1 sibling, 0 replies; 15+ messages in thread
From: Daniel Santos @ 2017-04-24 15:00 UTC (permalink / raw)
To: cygwin
On 04/24/2017 02:00 AM, Mark Geisert wrote:
>
> Excellent debugging work! I'm inclined to agree with your last
> point. I'm poring over pinfo.cc as well as dcrt0.cc, which is the
> Cygwin DLL init code. The latter talks about special cases if the DLL
> is runtime loaded (like strace does) vs link-time loaded (like Cygwin
> apps do). May take me a while to respond.
Hah! me too. :) At least I'm learning a lot. I have a better
understanding of how it stores these in the windows object database
thing under \\BaseNamedObjects and I can browse it to some degree with
WinObj from sysinternals, but I'm still trying to figure out where that
is initialized. My tests will be done soon and I'll be back to work on gcc.
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
* Re: long I/O delays when strace is running
2017-04-24 9:34 ` Mark Geisert
2017-04-24 15:00 ` Daniel Santos
@ 2017-04-24 19:30 ` Daniel Santos
1 sibling, 0 replies; 15+ messages in thread
From: Daniel Santos @ 2017-04-24 19:30 UTC (permalink / raw)
To: cygwin
I finally found a solution and submitted a patch, but I don't know if
it's the correct fix or not.
Daniel
--
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
^ permalink raw reply [flat|nested] 15+ messages in thread
end of thread, other threads:[~2017-04-24 9:34 UTC | newest]
Thread overview: 15+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-04-20 18:13 long I/O delays when strace is running Daniel Santos
2017-04-21 0:11 ` Gluszczak, Glenn
2017-04-21 7:57 ` Daniel Santos
2017-04-21 9:38 ` Daniel Santos
2017-04-21 11:06 ` Daniel Santos
2017-04-21 12:08 ` Mark Geisert
2017-04-21 18:23 ` Daniel Santos
2017-04-22 15:24 ` Mark Geisert
2017-04-23 12:58 ` Daniel Santos
2017-04-23 18:15 ` Mark Geisert
2017-04-24 8:23 ` Daniel Santos
2017-04-24 9:24 ` Daniel Santos
2017-04-24 9:34 ` Mark Geisert
2017-04-24 15:00 ` Daniel Santos
2017-04-24 19:30 ` Daniel Santos
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).