From owner-freebsd-hackers@freebsd.org Mon Mar 27 16:49:12 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 9CFC0D20931 for ; Mon, 27 Mar 2017 16:49:12 +0000 (UTC) (envelope-from kostikbel@gmail.com) Received: from kib.kiev.ua (kib.kiev.ua [IPv6:2001:470:d5e7:1::1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 4522AC73; Mon, 27 Mar 2017 16:49:12 +0000 (UTC) (envelope-from kostikbel@gmail.com) Received: from tom.home (kib@localhost [127.0.0.1]) by kib.kiev.ua (8.15.2/8.15.2) with ESMTPS id v2RGn64x019079 (version=TLSv1.2 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=NO); Mon, 27 Mar 2017 19:49:06 +0300 (EEST) (envelope-from kostikbel@gmail.com) DKIM-Filter: OpenDKIM Filter v2.10.3 kib.kiev.ua v2RGn64x019079 Received: (from kostik@localhost) by tom.home (8.15.2/8.15.2/Submit) id v2RGn5MM019078; Mon, 27 Mar 2017 19:49:06 +0300 (EEST) (envelope-from kostikbel@gmail.com) X-Authentication-Warning: tom.home: kostik set sender to kostikbel@gmail.com using -f Date: Mon, 27 Mar 2017 19:49:05 +0300 From: Konstantin Belousov To: Steven Hartland Cc: "K. Macy" , "freebsd-hackers@freebsd.org" Subject: Re: Help needed to identify golang fork / memory corruption issue on FreeBSD Message-ID: <20170327164905.GN43712@kib.kiev.ua> References: <20161206143532.GR54029@kib.kiev.ua> <18b40a69-4460-faf2-c0ce-7491eca92782@multiplay.co.uk> <20170317082333.GP16105@kib.kiev.ua> <180a601b-5481-bb41-f7fc-67976aabe451@multiplay.co.uk> <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> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <3ec35a46-ae70-35cd-29f8-82e7cebb0eb6@multiplay.co.uk> User-Agent: Mutt/1.8.0 (2017-02-23) X-Spam-Status: No, score=-2.0 required=5.0 tests=ALL_TRUSTED,BAYES_00, DKIM_ADSP_CUSTOM_MED,FREEMAIL_FROM,NML_ADSP_CUSTOM_MED autolearn=no autolearn_force=no version=3.4.1 X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on tom.home 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: Mon, 27 Mar 2017 16:49:12 -0000 On Mon, Mar 27, 2017 at 05:33:49PM +0100, Steven Hartland wrote: > On 27/03/2017 17:18, Konstantin Belousov wrote: > > On Mon, Mar 27, 2017 at 12:47:11PM +0100, Steven Hartland wrote: > >> OK now the similar but unrelated issue with signal stacks is solved I've > >> moved back to the initial issue. > >> > >> I've made some progress with a reproduction case as detailed here: > >> https://github.com/golang/go/issues/15658#issuecomment-288747812 > >> > >> In short it seems that having a running child, while the parent runs GC, > >> is some how responsible for memory corruption in the parent. > >> > >> The reason I believe this is if I run the same GC in the parent after > >> the child exits instead of while its running, I've been unable to > >> reproduce the issue. > >> > >> As the memory segments are COW then the issue might be in VM subsystem. > > Well, it might be, but it is a strange corruption mode to believe. > Indeed, but would you agree the evidence seems to indicate that this may > be the case, as otherwise I would have expected that running the GC > after the child process has exited would have zero impact on the issue. > > > >> In order to confirm / deny this I was wondering if there was a way to > >> force a full copy of all segments for the child instead of using the COW > >> optimisation. > > No, there is no. By design, copying only occurs on faults, when VM > > detects that the map entry needs copying. Doing the actual copy at fork > > time would require writing a lot of new code. > I noticed in vm_map_copy_entry the following: > /* > * We don't want to make writeable wired pages > copy-on-write. > * Immediately copy these pages into the new map by > simulating > * page faults. The new pages are pageable. > */ > vm_fault_copy_entry(dst_map, src_map, dst_entry, src_entry, > fork_charge); > > I wondered if I could use vm_fault_copy_entry to force the copy on fork? No, the vm_fault_copy_entry() only works with wired entries, e.g. it cannot page in not yet touched page, and the result is also wired. > > Does go have FreeBSD/i386 port ? If yes, is the issue reproducable there ? > Yes it does, I don't currently have i386 machine to test with, I'm > assuming testing i386 on amd64 kernel, would likely not have any effect. Only if the bug is in kernel and not in the go runtime. I am still not convinced that the kernel is the culprit. > > Another blind experiment to try is to comment out call to > > vm_object_collapse() in sys/vm/vm_map.c:vm_map_copy_entry() and see if > > it changes anything. > I'll do that shortly. > > What could be quite interesting is to look at the parent and possibly > > child address map after the error occured, using procstat -v. At > > least for parent, this should be relatively easy to set up, just make > > go runtime spin or pause on panic, instead of exiting, and then use > > procstat. > I've been looking at the output from procstat -v I have seen the parent > FLAGS ping ping between C--- and CN--, not sure if that's relevant e.g. C means that the entry is COW, N means that COW was not yet applied after the last fork, i.e. there were no write access. I am interested in the procstat -v output after the failure. I understand that there should be no surprising data for normally executing code. > procstat -v 27099 > PID START END PRT RES PRES REF SHD FLAG > TP PATH > 27099 0x400000 0x70d000 r-x 309 635 3 1 CN-- vn > /root/golang/src/test5/test5 > 27099 0x70d000 0x94e000 r-- 270 635 3 1 CN-- vn > /root/golang/src/test5/test5 > 27099 0x94e000 0x985000 rw- 55 0 1 0 C--- vn > /root/golang/src/test5/test5 > 27099 0x985000 0x9a8000 rw- 18 18 1 0 C--- df > 27099 0x80094e000 0x800b4e000 rw- 38 38 1 0 C--- df > 27099 0x800b4e000 0x800c1e000 rw- 28 28 1 0 C--- df > 27099 0x800c1e000 0x800c6e000 rw- 18 18 1 0 C--- df > 27099 0x800c6e000 0x800cae000 rw- 2 2 1 0 C--- df > 27099 0x800cae000 0x800cee000 rw- 2 2 1 0 C--- df > 27099 0x800cee000 0x800dae000 rw- 5 5 1 0 C--- df > 27099 0x800dae000 0x800dee000 rw- 1 1 1 0 C--- df > 27099 0x800dee000 0x800e2e000 rw- 1 1 1 0 C--- df > 27099 0x800e2e000 0x800e6e000 rw- 1 1 1 0 C--- df > 27099 0x800e6e000 0x800eae000 rw- 1 1 1 0 C--- df > 27099 0xc000000000 0xc000001000 rw- 1 1 1 0 CN-- df > 27099 0xc41fff0000 0xc41fff8000 rw- 3 3 1 0 CN-- df > 27099 0xc41fff8000 0xc420200000 rw- 255 255 1 0 C--- df > 27099 0x7ffffffdf000 0x7ffffffff000 rwx 2 2 1 0 C--D df > 27099 0x7ffffffff000 0x800000000000 r-x 1 1 37 0 ---- ph > > procstat -v 27099 > PID START END PRT RES PRES REF SHD FLAG > TP PATH > 27099 0x400000 0x70d000 r-x 309 635 5 1 CN-- vn > /root/golang/src/test5/test5 > 27099 0x70d000 0x94e000 r-- 270 635 5 1 CN-- vn > /root/golang/src/test5/test5 > 27099 0x94e000 0x985000 rw- 55 0 1 0 C--- vn > /root/golang/src/test5/test5 > 27099 0x985000 0x9a8000 rw- 18 0 1 0 C--- df > 27099 0x80094e000 0x800b4e000 rw- 38 38 2 0 CN-- df > 27099 0x800b4e000 0x800c1e000 rw- 28 28 2 0 CN-- df > 27099 0x800c1e000 0x800c6e000 rw- 18 18 2 0 CN-- df > 27099 0x800c6e000 0x800cae000 rw- 2 2 2 0 CN-- df > 27099 0x800cae000 0x800cee000 rw- 2 2 2 0 CN-- df > 27099 0x800cee000 0x800dae000 rw- 5 5 2 0 CN-- df > 27099 0x800dae000 0x800dee000 rw- 1 1 2 0 CN-- df > 27099 0x800dee000 0x800e2e000 rw- 1 1 2 0 CN-- df > 27099 0x800e2e000 0x800e6e000 rw- 1 1 2 0 CN-- df > 27099 0x800e6e000 0x800eae000 rw- 1 1 2 0 CN-- df > 27099 0xc000000000 0xc000001000 rw- 1 1 2 0 CN-- df > 27099 0xc41fff0000 0xc41fff8000 rw- 3 3 2 0 CN-- df > 27099 0xc41fff8000 0xc420200000 rw- 255 255 1 0 C--- df > 27099 0x7ffffffdf000 0x7ffffffff000 rwx 2 2 1 0 CN-D df > 27099 0x7ffffffff000 0x800000000000 r-x 1 1 38 0 ---- ph > > procstat -v 27099 > PID START END PRT RES PRES REF SHD FLAG > TP PATH > 27099 0x400000 0x70d000 r-x 309 635 5 1 CN-- vn > /root/golang/src/test5/test5 > 27099 0x70d000 0x94e000 r-- 270 635 5 1 CN-- vn > /root/golang/src/test5/test5 > 27099 0x94e000 0x985000 rw- 55 0 1 0 C--- vn > /root/golang/src/test5/test5 > 27099 0x985000 0x9a8000 rw- 18 0 1 0 C--- df > 27099 0x80094e000 0x800b4e000 rw- 38 0 1 0 C--- df > 27099 0x800b4e000 0x800c1e000 rw- 28 28 2 0 CN-- df > 27099 0x800c1e000 0x800c6e000 rw- 18 0 1 0 C--- df > 27099 0x800c6e000 0x800cae000 rw- 2 2 2 0 CN-- df > 27099 0x800cae000 0x800cee000 rw- 2 2 2 0 CN-- df > 27099 0x800cee000 0x800dae000 rw- 5 5 2 0 CN-- df > 27099 0x800dae000 0x800dee000 rw- 1 1 2 0 CN-- df > 27099 0x800dee000 0x800e2e000 rw- 1 0 1 0 C--- df > 27099 0x800e2e000 0x800e6e000 rw- 1 1 2 0 CN-- df > 27099 0x800e6e000 0x800eae000 rw- 1 1 2 0 CN-- df > 27099 0xc000000000 0xc000001000 rw- 1 1 2 0 CN-- df > 27099 0xc41fff0000 0xc41fff8000 rw- 3 3 2 0 CN-- df > 27099 0xc41fff8000 0xc420200000 rw- 255 0 1 0 C--- df > 27099 0x7ffffffdf000 0x7ffffffff000 rwx 2 2 1 0 C--D df > 27099 0x7ffffffff000 0x800000000000 r-x 1 1 38 0 ---- ph > > I'll definitely try capturing the output on fault, see what that looks like > > > >> Is this something that would be relatively easy to hack into the kernel, > >> and if so pointers would be appreciated. > > BTW, I looked some more at the go code, and I noted that > > runtimemmap() implementation looks very strange. > > It ignores %rflags.C bit to identify error, and instead callers > > of mmap() compare the return value with 4096, assuming Linux-style > > error reporting. This would certainly break if mmap(2) syscall > > returns ERESTART one day. > I'll look at this too, thanks for the heads up. > > Regards > Steve