long I/O delays when strace is running

[Daniel Santos]

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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ps.log
Type: text/x-log
Size: 48605 bytes
Desc: not available
URL: <http://cygwin.com/pipermail/cygwin/attachments/20170421/d2c98094/attachment.bin>
-------------- next part --------------

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