From owner-freebsd-hackers@freebsd.org Tue Mar 28 22:50:40 2017 Return-Path: Delivered-To: freebsd-hackers@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id CA829D23F82 for ; Tue, 28 Mar 2017 22:50:40 +0000 (UTC) (envelope-from killing@multiplay.co.uk) Received: from mail-wm0-x229.google.com (mail-wm0-x229.google.com [IPv6:2a00:1450:400c:c09::229]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 59FB81350 for ; Tue, 28 Mar 2017 22:50:40 +0000 (UTC) (envelope-from killing@multiplay.co.uk) Received: by mail-wm0-x229.google.com with SMTP id u132so50889967wmg.0 for ; Tue, 28 Mar 2017 15:50:39 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=multiplay-co-uk.20150623.gappssmtp.com; s=20150623; h=subject:to:references:cc:from:message-id:date:user-agent :mime-version:in-reply-to; bh=P18p0gQK25xTrHDARDdvr9TcHGtk46aqOnJujkDB/NQ=; b=jj1Nlg4VTFNu3xezRamK5bT4cTclJykrx3GgZLKAfcPw12/3ogRCepu360npYoTQ+5 LjBr0CoTrtruhH8OrKJsi+SRqtHhsm0IlsDFZLyhfAbVerUlL086BsgPh67yrBJopywL 2CWhpBx/hoSnru7wVmT87HMGMO4KctNtmZ/sOxM22EGbrPt07G+k0tT/Ifr8EjINO+yp TC4LpHhgD7c7NsyVo5HrLpo6Ow0C1AZvmH4bHBXm0SbF17MV/gBEP6hqtNkb7UyzpuaN UWBvMWeSdTJy2aiZoAxcEZSHrKrFJbTO2beAS7nIanhgSwJwEmgQRiw/Elessle+o7q+ qkhw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:references:cc:from:message-id:date :user-agent:mime-version:in-reply-to; bh=P18p0gQK25xTrHDARDdvr9TcHGtk46aqOnJujkDB/NQ=; b=LUvpr1kCC67h4Zpxbt6xcmTkHwuCd8qaHqX6sL0l8HjwrybBIK8XRFsoK1mOndRt53 N1bwszd1SycOEW8pMQ2eWYJXKHlJqIpHCgRZCzzreLCH411QP/zO6I+s9HpojN/Y1HXe Q7Pe+z8Eg1fbpTEumJWrtKAM3wuRYTNUrhg7Xk5Ud3jbty2q0yjSMCKYNXz2JDw/UPcz e78ZTPiTvLsu4rZYmYlmC1T2xuF/5Fn1Et7VqjXJ+WwVNwcX4xcTPJFcwck/L7+/Rr5v 7zdfakf7nWY/C2ReBiuk1GO5/CkMCIOHPEQ0pW48ZsTm2mG78gO4HNFWhqfRpCrw+AvQ nnZg== X-Gm-Message-State: AFeK/H30Omy03L/wwCjQF66Ucw9px8Uok7ZpTV6BIz9Rj9FMXHR3WejVhy74o+lU5nl3qc+c X-Received: by 10.28.0.136 with SMTP id 130mr16781120wma.126.1490741438475; Tue, 28 Mar 2017 15:50:38 -0700 (PDT) Received: from [10.10.1.58] ([185.97.61.26]) by smtp.gmail.com with ESMTPSA id y107sm6585640wrc.35.2017.03.28.15.50.37 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 28 Mar 2017 15:50:37 -0700 (PDT) Subject: Re: Help needed to identify golang fork / memory corruption issue on FreeBSD To: Konstantin Belousov References: <20170317124437.GR16105@kib.kiev.ua> <5ba92447-945e-6fea-ad4f-f58ac2a0012e@multiplay.co.uk> <20170327161833.GL43712@kib.kiev.ua> <3ec35a46-ae70-35cd-29f8-82e7cebb0eb6@multiplay.co.uk> <20170327164905.GN43712@kib.kiev.ua> <17f29342-f3c0-5940-d012-1a698e59a384@multiplay.co.uk> <20170328075859.GQ43712@kib.kiev.ua> <85f86a20-948f-025a-0d09-92ee2a815136@multiplay.co.uk> <20170328083810.GR43712@kib.kiev.ua> <5aa653ba-30e1-c9de-46ce-bad74d78c40c@multiplay.co.uk> <20170328113859.GS43712@kib.kiev.ua> Cc: "K. Macy" , "freebsd-hackers@freebsd.org" From: Steven Hartland Message-ID: <2f5952b5-104d-4e82-5ebe-8cb9caabedae@multiplay.co.uk> Date: Tue, 28 Mar 2017 23:50:37 +0100 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:45.0) Gecko/20100101 Thunderbird/45.8.0 MIME-Version: 1.0 In-Reply-To: <20170328113859.GS43712@kib.kiev.ua> Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit X-Content-Filtered-By: Mailman/MimeDel 2.1.23 X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 28 Mar 2017 22:50:40 -0000 On 28/03/2017 12:38, Konstantin Belousov wrote: > On Tue, Mar 28, 2017 at 09:48:23AM +0100, Steven Hartland wrote: >> On 28/03/2017 09:38, Konstantin Belousov wrote: >>> On Tue, Mar 28, 2017 at 09:23:24AM +0100, Steven Hartland wrote: >>>> As I stopped the panic before that I couldn't tell so I've re-run with >>>> some debug added just before the panic to capture the addresses of the >>>> workbuf structure that the issue was detected in, here goes (parent: >>>> 62620, child: 98756): >>>> >>>> workbuf: 0x800b51800 >>>> fatal error: workbuf is not empty >>>> workbuf: 0x800a72000 >>>> fatal error: workbuf is empty >>>> workbuf: 0x800a72000 >>>> fatal error: workbuf is not empty >>> I do not understand. Why do you show several addresses ? Wouldn't the >>> runtime panic after detecting the discrepancy, so there could be only one >>> address ? >> There are several goroutines (threads) running each detected an error, >> as I'm blocking the panic by entering a sleep in the faulting goroutine >> to enable the capture of procstat, other routines continue and detect an >> error too. > Ok. > > So I tried to simulate the load with an isolated test. Code below is > naive, but it should illustrate the idea. Parent allocates some > number of private-mapped areas, then runs threads which write bytes into > the areas. Simultaneously parent forks children which write distinct > byte into the same anonymous memory. > > Parent checks that it cannot see a byte written by children. > > So far it did not tripped on my test machine. Feel free to play with it, > if you have more insights what go runtime does, modify the code to simulate > the failing test more accurately. I've updated to it to be more like the go, so single forking thread (non-main), ancillary threads mainly idle until triggered by forking thread to perform a check, and still no failure. What's curious is why I don't get the issue if either: 1. The machine has just a single core. 2. The work (GC) is moved after the child wait. Given the above I added some debug: func (b *workbuf) checknonempty() { if b.nobj == 0 { print("workbuf is empty: b: ", b, ", nobj: ", b.nobj, ", nobj2: ", b.nobj2, ", pushcnt: ", b.node.pushcnt, "\n") throw("workbuf is empty") } } func (b *workbuf) checkempty() { if b.nobj != 0 { print("workbuf is not empty: b: ", b, ", nobj: ", b.nobj, ", nobj2: ", b.nobj2, ", pushcnt: ", b.node.pushcnt, "\n") throw("workbuf is not empty") } } Here's the output: workbuf is not empty: b: 0x800c51000, nobj: 4, nobj2: -2, pushcnt: 104881 fatal error: workbuf is not empty Nothing strange, but now lets have a look using gdb after the parent has exited: (gdb) frame 8 #8 0x000000000041f1e8 in runtime.(*workbuf).checkempty (b=0x800c51000) at /usr/local/go/src/runtime/mgcwork.go:328 328 throw("workbuf is not empty") (gdb) print b $3 = (struct runtime.workbuf *) 0x800c51000 (gdb) print *b $4 = {runtime.workbufhdr = {node = {next = 0, pushcnt = 104881}, nobj = 0, nobj2 = -8},.... So after the error was printed the value for nobj was some how corrected, however nobj2 being -8 indicates the last call which altered nobj was func (w *gcWork) get() uintptr where as the -2 indicates it was a putfull which is very muddled up. I was curious what the child had at 0x800c51000 but couldn't persuade gdb to cast and output it as a struct runtime.workbuf. Regards Steve