X-Recipient: archive-cygwin AT delorie DOT com
DomainKey-Signature: a=rsa-sha1; c=nofws; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:subject:to:references:from:message-id:date
	:mime-version:in-reply-to:content-type
	:content-transfer-encoding; q=dns; s=default; b=Wz+Qxmplud2/2Vz1
	9oXihPOF2ftmUnLWsNMP/f30/PxzyxShV6WNT8DEweUG7Hb0rWDyxA+BwA+IODAu
	3TH2+OYZ5cgI3m3A1smqZuupb2um6QgVKjQiyD5SJzCaSTy8TFcDoJ0kbeAg2F+C
	0sapTQRttkAiPU6IAo7SkSlNZ/I=
DKIM-Signature: v=1; a=rsa-sha1; c=relaxed; d=sourceware.org; h=list-id
	:list-unsubscribe:list-subscribe:list-archive:list-post
	:list-help:sender:subject:to:references:from:message-id:date
	:mime-version:in-reply-to:content-type
	:content-transfer-encoding; s=default; bh=5a+24tIFQzWVRVs+c56a8v
	RqBOw=; b=rRgUM/RZw0gFmnnZMYhz958G9nHMGValnyC9dwib8GJS/NySndsdiK
	JX2WozluKVFWFxyHKjPk1vIQxXy0FIk0CSy9PGGOA5TTYmhLqpibQtspdJC9ZwRl
	HhEOXhW521jOtuQNw9Dh82v+d3cJ/I0J81IJkaAnXPvdgZKsOMhwU=
Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm
List-Id: <cygwin.cygwin.com>
List-Subscribe: <mailto:cygwin-subscribe AT cygwin DOT com>
List-Archive: <http://sourceware.org/ml/cygwin/>
List-Post: <mailto:cygwin AT cygwin DOT com>
List-Help: <mailto:cygwin-help AT cygwin DOT com>, <http://sourceware.org/ml/#faqs>
Sender: cygwin-owner AT cygwin DOT com
Mail-Followup-To: cygwin AT cygwin DOT com
Delivered-To: mailing list cygwin AT cygwin DOT com
Authentication-Results: sourceware.org; auth=none
X-Virus-Found: No
X-Spam-SWARE-Status: No, score=-0.7 required=5.0 tests=AWL,BAYES_00,KAM_LAZY_DOMAIN_SECURITY autolearn=no version=3.3.2 spammy=humble, H*r:8.12.11, ended, 054
X-HELO: m0.truegem.net
Subject: Re: long I/O delays when strace is running
To: cygwin AT cygwin DOT com
References: <be8713ec-5b68-e0e9-c5a5-d48fce491a2d AT pobox DOT com> <91DCAC3CB99C724EB365BB64677FBE7B16EBBD AT MX204CL04 DOT corp DOT emc DOT com> <46e39bce-9782-5c74-c196-35ee97ebbc64 AT pobox DOT com> <ace81c86-80d5-bef9-6b93-7d36dde5a4e8 AT pobox DOT com> <bff9c5ea-85d9-bf4e-2f25-271c1490565f AT pobox DOT com>
From: Mark Geisert <mark AT maxrnd DOT com>
Message-ID: <58F9D314.2000100@maxrnd.com>
Date: Fri, 21 Apr 2017 02:38:28 -0700
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:43.0) Gecko/20100101 Firefox/43.0 SeaMonkey/2.40
MIME-Version: 1.0
In-Reply-To: <bff9c5ea-85d9-bf4e-2f25-271c1490565f@pobox.com>
Content-Type: text/plain; charset=windows-1252; format=flowed
Content-Transfer-Encoding: 7bit

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