X-Recipient: archive-cygwin AT delorie DOT com X-SWARE-Spam-Status: No, hits=-0.9 required=5.0 tests=AWL,BAYES_20,RCVD_IN_HOSTKARMA_NO,RCVD_IN_HOSTKARMA_YE,RP_MATCHES_RCVD X-Spam-Check-By: sourceware.org To: cygwin AT cygwin DOT com Subject: Runaway process under xemacs 21.5 / latest cygwin or snapshot From: ht AT inf DOT ed DOT ac DOT uk (Henry S. Thompson) Date: Wed, 20 Feb 2013 22:00:27 +0000 Message-ID: User-Agent: Gnus/5.101 (Gnus v5.10.10) XEmacs/21.5-b32 (linux) MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii X-Edinburgh-Scanned: at nougat.ucs.ed.ac.uk with MIMEDefang 2.60, Sophie, Sophos Anti-Virus, Clam AntiVirus X-IsSubscribed: yes Mailing-List: contact cygwin-help AT cygwin DOT com; run by ezmlm List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: cygwin-owner AT cygwin DOT com Mail-Followup-To: cygwin AT cygwin DOT com Delivered-To: mailing list cygwin AT cygwin DOT com Headline symptoms -- some time after visiting a file containing code (doesn't matter what -- at least php, emacs lisp and c), xemacs freezes while consuming one full processor, two threads, on my 2CPU4Thread machine, i.e. 25% each. Can't be killed with ^C or by trying to close the window. Process Explorer says the thread stacks look like this (each one is burning 25% constantly): thread 9800 wow64cpu.dll!TurboDispatchJumpAddressEnd+0x6c0 wow64cpu.dll!TurboDispatchJumpAddressEnd+0x56b wow64.dll!Wow64SystemServiceEx+0x1ce wow64.dll!Wow64LdrpInitialize+0x429 ntdll.dll!RtlIsDosDeviceName_U+0x24c87 ntdll.dll!LdrInitializeThunk+0xe ntdll.dll!ZwDelayExecution+0x15 cygwin1.dll!lfind+0x4529 cygwin1.dll!_getenv+0x555d cygwin1.dll!sigfillset+0x28ec cygwin1.dll!setprogname+0x1d05 cygwin1.dll!setprogname+0x228f cygwin1.dll!setprogname+0x2e41 thread 9980 ntdll.dll!NtSetInformationThread+0xa wow64.dll!Wow64EmulateAtlThunk+0x1674 wow64.dll!Wow64SystemServiceEx+0xd7 wow64cpu.dll!TurboDispatchJumpAddressEnd+0x2d wow64.dll!Wow64SystemServiceEx+0x1ce wow64.dll!Wow64LdrpInitialize+0x429 ntdll.dll!RtlIsDosDeviceName_U+0x24c87 ntdll.dll!LdrInitializeThunk+0xe ntdll.dll!ZwSetInformationThread+0x12 cygwin1.dll!lfind+0x453d xemacs+0x2030ba xemacs+0x7c75d xemacs+0x1eaa7e xemacs+0x2316b8 xemacs+0x2316f3 WINMM.DLL!DriverCallback+0x4e WINMM.DLL!timeEndPeriod+0x54a WINMM.DLL!timeEndPeriod+0x449 cygwin1.dll!setprogname+0x31dd strace is stopped, i.e. adding no new lines, with the last 20 looking like this: 42 201182701 [main] xemacs 9540 fhandler_pipe::create: 0 = pipe([0x612778E8, 0x612790A8], 65536, 0x10000) 44 201182745 [main] xemacs 9540 pipe: 0 = pipe([8, 9]) 46 201182791 [main] xemacs 9540 fcntl64: fcntl(6, 4, ...) 39 201182830 [main] xemacs 9540 fhandler_base::set_flags: flags 0x14000, supplied_bin 0x0 38 201182868 [main] xemacs 9540 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000 40 201182908 [main] xemacs 9540 fhandler_base::set_flags: filemode set to binary 36 201182944 [main] xemacs 9540 fcntl64: 0 = fcntl(6, 4, 0x4000) 36 201182980 [main] xemacs 9540 fcntl64: fcntl(9, 4, ...) 42 201183022 [main] xemacs 9540 fhandler_base::set_flags: flags 0x14001, supplied_bin 0x0 43 201183065 [main] xemacs 9540 fhandler_base::set_flags: O_TEXT/O_BINARY set in flags 0x10000 40 201183105 [main] xemacs 9540 fhandler_base::set_flags: filemode set to binary 41 201183146 [main] xemacs 9540 fcntl64: 0 = fcntl(9, 4, 0x4000) 49 201183195 [main] xemacs 9540 fhandler_pipe::lseek: (0, 0) 36 201183231 [main] xemacs 9540 __set_errno: virtual _off64_t fhandler_pipe::lseek(_off64_t, int):149 setting errno 29 37 201183268 [main] xemacs 9540 lseek64: -1 = lseek(6, 0, 1), errno 29 49 201183317 [main] xemacs 9540 fhandler_pipe::lseek: (0, 0) 47 201183364 [main] xemacs 9540 __set_errno: virtual _off64_t fhandler_pipe::lseek(_off64_t, int):149 setting errno 29 41 201183405 [main] xemacs 9540 lseek64: -1 = lseek(9, 0, 1), errno 29 55 201183460 [main] xemacs 9540 child_info::child_info: subproc_ready 0x3CC 47 201183507 [main] xemacs 9540 fork: entering 269 201183776 [main] xemacs 9540 sig_send: sendsig 0xA4, pid 9540, signal -40, its_me 1 41 201183817 [main] xemacs 9540 sig_send: wakeup 0x470 The problem occurs with a clean build of xemacs (and has done over a number of recent versions) and with current cygwin and 20130131 snapshot, as well as for some months past. Some aspect of the semantic package, which analyses code and its neighbours, is the high-level source of the problem, in that what seems to trigger it is semantic going to work scanning files in the neighbourhood, but I'm having a hard time getting any clear evidence -- I _suspect_ something to do with pipes/threads/signalling, but I'm a novice in that area. I realise there's not enough evidence here to pin things down, much less make them reproducible without all of xemacs, but I'm really asking for suggestions for how to gather evidence which _will_ show what's happening. It is conceivably relevant that xemacs did 883 140901870 [main] xemacs 5432 spawnve: spawnve (/c/Cygwin/bin/git.exe, /c/Cygwin/bin/git.exe, 285B80) not long before hanging. Looking through the strace output, this was the second time it did that (on other occasions, it's done 5 or 6 before getting stuck), and the outcome is apparently different in the two cases - is there evidence of a race condition here: Successful case, a page or so after ExitProcess called in the git process (9916): 46 80515966 [waitproc] xemacs 9540 proc_waiter: exiting wait thread for pid 9916 14 80515980 [sig] xemacs 9540 sigpacket::process: signal 20, signal handler 0x583011 40 80516020 [sig] xemacs 9540 sigpacket::setup_handler: controlled interrupt. stackptr 0x28DA34, stack 0x28DA30, stackptr[-1] 0x602F71 28 80516048 [sig] xemacs 9540 proc_subproc: args: 5, 1 24 80516072 [sig] xemacs 9540 proc_subproc: clear waiting threads 25 80516097 [sig] xemacs 9540 proc_subproc: finished clearing -47 80516050 [main] xemacs 9540 fhandler_base::read: returning 0, binary mode 70 80516120 [sig] xemacs 9540 proc_subproc: returning 1 About to get stuck case, likewise after ExitProcess called in the git process (5432): 25 140953042 [waitproc] xemacs 9540 proc_waiter: exiting wait thread for pid 5432 58 140953100 [main] xemacs 9540 stopped_or_terminated: considering pid 5432, pgid 5432, w->pid 5432 52 140953152 [sig] xemacs 9540 sigpacket::process: signal 20, signal handler 0x583011 26 140953178 [main] xemacs 9540 remove_proc: removing procs[0], pid 5432, nprocs 1 31 140953209 [sig] xemacs 9540 sigpacket::setup_handler: thread handle NULL, not set up yet? 83 140953292 [sig] xemacs 9540 sigpacket::setup_handler: couldn't interrupt. trying again. 45 140953337 [main] xemacs 9540 checkstate: returning 1 33 140953370 [main] xemacs 9540 proc_subproc: released waiting thread 29 140953399 [main] xemacs 9540 proc_subproc: finished processing terminated/stopped child 29 140953428 [main] xemacs 9540 proc_subproc: returning 1 31 140953459 [main] xemacs 9540 wait4: 0 = cygwait (...) Thanks for any suggestions on how to proceed, ht -- Henry S. Thompson, School of Informatics, University of Edinburgh 10 Crichton Street, Edinburgh EH8 9AB, SCOTLAND -- (44) 131 650-4440 Fax: (44) 131 650-4587, e-mail: ht AT inf DOT ed DOT ac DOT uk URL: http://www.ltg.ed.ac.uk/~ht/ [mail from me _always_ has a .sig like this -- mail without it is forged spam] -- 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