Web lists-archives.com

Re: long I/O delays when strace is running




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

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