Re: runtime regression with "x86/mm/pat: Emulate PAT when it is disabled"

[Toshi Kani <toshi.kani@hpe.com>]

On Fri, 2016-03-04 at 13:37 -0500, Paul Gortmaker wrote:
> [Re: runtime regression with "x86/mm/pat: Emulate PAT when it is
> disabled"] On 03/03/2016 (Thu 22:02) Toshi Kani wrote:
> 
> > On Thu, 2016-03-03 at 15:59 -0500, Paul Gortmaker wrote:
 :
> > > 
> > > The stand alone reproducer is here; launched in 00-runme:
> > > 
> > > http://openlinux.wrs.com/pat-splat/reproducer.tar.bz2  
> > > 
> > > It is nothing fancy, just a generic yocto build of "sato" (gfx
> > > enabled rootfs).  When it "works" it boots to a UI touchscreen
> > > interface.  When
> > > it fails, you get a black screen with a blinking cursor (as seen in
> > > "vncviewer localhost:0").
> > 
> > Thanks for tracking down, and packaging the reproducer.  I simply
> > untar'd and ran 00-runme, but was not able to connect with localhost:0.
> >  I am not familiar with qemu, so I have not looked into why, though...
> 
> Maybe it was localhost:1 in your case?  The qemu should have indicated
> what vncserver sessions it started.  Can you paste in the output from
> the 00-runme?   I tested the reproducer on a machine that was physically
> distinct from the build, and that was a generic ubuntu install, but with
> no qemu support installed at all and it worked there.  Plus I got Bruce
> to test it worked on his machine, so I'm rather surprised it did not
> work for you.

I am not really sure what I am doing is correct.

On one window:
# ./00-runme
Warning: vlan 0 is not connected to host network
VNC server running on '::1:5900'

And another window on the same system:
# vncviewer localhost:1

TigerVNC Viewer 64-bit v1.6.0
Built on: 2016-01-04 15:09
Copyright (C) 1999-2015 TigerVNC Team and many others (see README.txt)
See http://www.tigervnc.org for information on TigerVNC.
Can't open display: 

> > Anyway, with regarding the error message:
> >   "x86/PAT: Xorg:705 map pfn expected mapping type uncached-minus for
> > [mem
> > 0xfd000000-0xfdffffff], got write-combining"
> > 
> > Did it came from the following path during fork()?
> >  copy_process
> >   copy_mm
> >    dup_mm
> >     dup_mmap
> >      copy_page_range
> >       track_pfn_copy
> >        reserve_pfn_range
> 
> The trace is consistent, and was already captured by Richard, as per:
> 
> http://lists.openembedded.org/pipermail/openembedded-core/2016-March/1183
> 97.html
> 
> which is the link given earlier.  When I say consistent, I mean that I
> get essentially the same thing when booting 4.5-rc6:

There are two issues here.
 1. copy_process() failed in the check in reserve_pfn_range()
 2. error path in copy_process() then hit WARN_ON_ONCE in untrack_pfn().

We are currently looking into #1, which Richard referred as:
| It appears that Xorg mmaps this from userspace, then later does a
| fork() to execute a utility. At this point, when creating the vmas for
| the new process, the pat code says "eeek!" as the protection mode for
| the new vmas don't match the old one, returns -EINVAL, the process dies
| and X goes with it.

Since it seemed that Richard had some analysis on #1, I wanted to confirm
that the failure path of #1 was the above stack trace.

The stack trace below shows the failure path of #2.

> [   30.098100] x86/PAT: Xorg:509 map pfn expected mapping type uncached-
> minus for [mem 0xfd000000-0xfdffffff], got write-combining
> [   30.106782] ------------[ cut here ]------------
> [   30.107093] WARNING: CPU: 0 PID: 509 at /home/paul/poky/build/tmp-
> glibc/work-shared/qemux86/kernel-source/arch/x86/mm/pat.c:986
> untrack_pfn+0x9f/0xb0()
> [   30.112553] Modules linked in: 8021q parport_pc parport floppy uvesafb
> [   30.113766] CPU: 0 PID: 509 Comm: Xorg Not tainted 4.5.0-rc6-yocto-
> standard #1
> [   30.113806] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
> [   30.114078]  00000000 00003286 c0149d78 c13a6c7f 00000000 00000000
> c0149dac c1052bcb
> [   30.114214]  c1ac7544 00000000 000001fd c1ac1ea4 000003da c104cbdf
> 000003da c104cbdf
> [   30.114214]  00000000 cdcf0528 00000000 c0149dbc c1052ca2 00000009
> 00000000 c0149de0
> [   30.114214] Call Trace:
> [   30.114214]  [<c13a6c7f>] dump_stack+0x58/0x79
> [   30.114214]  [<c1052bcb>] warn_slowpath_common+0x8b/0xc0
> [   30.114214]  [<c104cbdf>] ? untrack_pfn+0x9f/0xb0
> [   30.114214]  [<c104cbdf>] ? untrack_pfn+0x9f/0xb0
> [   30.114214]  [<c1052ca2>] warn_slowpath_null+0x22/0x30
> [   30.114214]  [<c104cbdf>] untrack_pfn+0x9f/0xb0
> [   30.114214]  [<c104ecf4>] ? __kunmap_atomic+0x54/0x110
> [   30.114214]  [<c114f1cf>] unmap_single_vma+0x56f/0x580
> [   30.114214]  [<c11321d0>] ? pagevec_move_tail_fn+0xa0/0xa0
> [   30.114214]  [<c1150123>] unmap_vmas+0x43/0x60
> [   30.114214]  [<c1154d5f>] exit_mmap+0x5f/0xf0
> [   30.114214]  [<c10507bd>] mmput+0x2d/0xa0
> [   30.114214]  [<c1051c19>] copy_process.part.47+0x1229/0x1430
> [   30.114214]  [<c1051fb4>] _do_fork+0xb4/0x3b0
> [   30.114214]  [<c105239c>] SyS_clone+0x2c/0x30
> [   30.114214]  [<c1001a04>] do_syscall_32_irqs_on+0x54/0xb0
> [   30.114214]  [<c18b06ca>] entry_INT80_32+0x2a/0x2a
> [   30.124383] ---[ end trace f7c8a5d94542f94e ]---
> 
> > 
> > If so, track_pfn_copy() obtained pgprot from a PTE, and called
> > reserve_pfn_range() with it.  So, the error message indicates that
> > previous ioremap_wc() (i.e. pcm WC) resulted in creating UC- map (i.e.
> > pgprot UC-).  pcm is a logical cache type and pgprot is a HW cache
> > type.  They can be different when CPU does not have support for a given
> > logical type.  This WC to UC- conversion happens when CPU does not
> > support PAT.
> > 
> > Richard's change, which compares with pgprot values in
> > reserve_pfn_range() is a good one, but I do not understand how we get
> > into this mess.  We do not have this check when PAT is disabled, and WC
> > is supported when PAT is enabled.
> > 
> > Commit 9cd25aac1 changed the initial values of the pcm<->pgrot
> > conversion tables.  The tables should be initialized with the same
> > values after pat_init() is called.  Is there any possibility that
> > ioremap_wc() was called before pat_init()..?
> 
> I don't think it is an initcall ordering thing; recall that I said the
> problem seems to go away when built-in vs uvesafb as module.  So given
> that, I think it is more related to where the code lands.

>From the failure, it looks as if pat_init() was not called at all, but I
cannot explain how built-in vs module can make such difference. 

> > Also, can you send me a whole dmesg output?  I'd like to check how PAT
> > is initialized.
> 
> I'll send the full file off list vs. spamming everyone with it.  I'm open
> to booting the pre-fail commit with PAT specific bootargs and the post-
> fail with the same and diffing the two dmesg if there are bootargs you'd
> like me to test.  I'd also like to ensure you have a working reproducer
> locally so maybe we should look at how that failed 1st.

Great.  Yes, two dmesg will be really helpful.

Thanks,
-Toshi