From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 9011 invoked by alias); 24 Apr 2017 07:00:51 -0000 Mailing-List: contact cygwin-help@cygwin.com; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner@cygwin.com Mail-Followup-To: cygwin@cygwin.com Received: (qmail 8854 invoked by uid 89); 24 Apr 2017 07:00:49 -0000 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=H*r:8.12.11, H*F:U*mark, work, work! X-HELO: m0.truegem.net Received: from m0.truegem.net (HELO m0.truegem.net) (69.55.228.47) by sourceware.org (qpsmtpd/0.93/v0.84-503-g423c35a) with ESMTP; Mon, 24 Apr 2017 07:00:47 +0000 Received: (from daemon@localhost) by m0.truegem.net (8.12.11/8.12.11) id v3O70mdI024191 for ; Mon, 24 Apr 2017 00:00:48 -0700 (PDT) (envelope-from mark@maxrnd.com) Received: from 76-217-5-154.lightspeed.irvnca.sbcglobal.net(76.217.5.154), claiming to be "[192.168.1.100]" via SMTP by m0.truegem.net, id smtpdNkjWcU; Mon Apr 24 00:00:46 2017 Subject: Re: long I/O delays when strace is running To: cygwin@cygwin.com References: <91DCAC3CB99C724EB365BB64677FBE7B16EBBD@MX204CL04.corp.emc.com> <46e39bce-9782-5c74-c196-35ee97ebbc64@pobox.com> <58F9D314.2000100@maxrnd.com> <7d56e728-32a3-9179-b002-e83880e297d0@pobox.com> <58FA83DB.3000209@maxrnd.com> <58FC5AFB.3010903@maxrnd.com> <00fb01d0-acdc-68da-e31e-45ffa7099043@pobox.com> From: Mark Geisert Message-ID: <58FDA29D.7080908@maxrnd.com> Date: Mon, 24 Apr 2017 09:34:00 -0000 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: <00fb01d0-acdc-68da-e31e-45ffa7099043@pobox.com> Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit X-SW-Source: 2017-04/txt/msg00308.txt.bz2 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