long I/O delays when strace is running

long I/O delays when strace is running

[Daniel Santos]

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

RE: long I/O delays when strace is running

[Gluszczak, Glenn]

[-- 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РÐ

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Mark Geisert]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Mark Geisert]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Mark Geisert]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Mark Geisert]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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

Re: long I/O delays when strace is running

[Daniel Santos]

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