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

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

[Paul Gortmaker]

So, the yocto folks moved from 4.1 to 4.4 and one of their automated
qemu x86-32 boot tests started failing.  None of the yocto details seem
to matter since I offered to help and I've repropduced it using 100%
mainline kernels and a generic distro toolchain as well.

The test case is slightly complicated, in that it relies on uvesafb
being modular, and so one has to juggle modules within an ext4 image
that qemu boots from.  We tried making uvesafb builtin, but that made
the issue magically vanish.  Given PAT, this isn't too surprising.

Richard did the preliminary investigation and analysis, and from that I
did a bisect, and found the commit in $SUBJECT to be the root cause, as
per the discussion here:

http://lists.openembedded.org/pipermail/openembedded-core/2016-March/118397.html

I'd mentioned the above to bpetkov on IRC and after confirming it was
still an issue on 4.5-rc6, he'd asked if I had a portable reproducer.  

Not sure how complicated that would be, I set out to make one from my
build.   With a little LD_PRELOAD type magic and ensuring all the qemu
components are in ./  I have one that runs on an otherwise qemu-free
x86-64 box. 

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").

Upon failure, you can do <Ctrl>-<Alt>-<2> to get to a passwd-less root
login ; there you can run dmesg and see the splat.  The image is
currently using 4.5-rc6 ; but any kernel can be inserted; "make
modules_install INSTALL_MOD_PATH=here" and then populating those modules
from "here" into /lib/modules of the loopback mounted image. And of
course updating the bzImage on the qemu cmdline.    Currently it
contains a bzImage and modules for 4.5-rc6 as I last tested that.

Also note that vncviewer will disconnect when it goes from early boot
80x25 to a higer res gfx mode; just reconnect and continue observing the
target.

I've ruled out yocto kernel changes, and yocto toolchain -- but maybe it
is a qemu issue this commit triggers ; who knows at this point.

Since I've NFI what component(s) cause this, I wanted to have the qemu
binary, all libraries etc as part of the reproducer and nothing left to
chance, and I've tested the reproducer on an ancient dual core w/o vmx
and w/o any qemu binaries installed.  Bruce also tested it on a slightly
more modern dual socket xeon with vmx and confirmed it failed there..

Inside there is a 00-runme ; mostly a copy of qemu args the yocto
automated tests were using.  There is also everything the qemu binaries
need to run ; toplevel dir is noisy since qemu only looks in ./ it
seems.  There is also an ext4.img ; as mentioned earlier, this only
happens when uvesafb.ko is a module, so one has to loopback mount that
image and repopulate /lib/modules/  for each boot test/bisect step.

I've also included 00-bisect.txt as the output of git bisect log.  And
there is also 00-configs/ dir that has the ".config" kernel file for
each build (dir names are "git describe" in here for easy correlation)
done for the bisect (plus the latest mainline build).  The failing commit
in the subject is v4.1-rc5-22-g9cd25aac1f44 .

My contribution here is largely a bisect that can be relied on and
providing a portable reproducer of the regression; I am by no means a
PAT expert ; Richard invested more time into actually understanding the
problem than I did, so I'm going to totally throw him under the bus on
this when it comes to considering the ultimate root cause and possible
fixes.  :)

Paul.
--

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

[Paul Gortmaker]

[runtime regression with "x86/mm/pat: Emulate PAT when it is disabled"] On 03/03/2016 (Thu 15:59) Paul Gortmaker wrote:

> So, the yocto folks moved from 4.1 to 4.4 and one of their automated
> qemu x86-32 boot tests started failing.  None of the yocto details seem
> to matter since I offered to help and I've repropduced it using 100%
> mainline kernels and a generic distro toolchain as well.
> 
> The test case is slightly complicated, in that it relies on uvesafb
> being modular, and so one has to juggle modules within an ext4 image
> that qemu boots from.  We tried making uvesafb builtin, but that made
> the issue magically vanish.  Given PAT, this isn't too surprising.
> 
> Richard did the preliminary investigation and analysis, and from that I
> did a bisect, and found the commit in $SUBJECT to be the root cause, as
> per the discussion here:
> 
> http://lists.openembedded.org/pipermail/openembedded-core/2016-March/118397.html
> 
> I'd mentioned the above to bpetkov on IRC and after confirming it was
> still an issue on 4.5-rc6, he'd asked if I had a portable reproducer.  
> 
> Not sure how complicated that would be, I set out to make one from my
> build.   With a little LD_PRELOAD type magic and ensuring all the qemu
> components are in ./  I have one that runs on an otherwise qemu-free
> x86-64 box. 
> 
> The stand alone reproducer is here; launched in 00-runme:
> 
> http://openlinux.wrs.com/pat-splat/reproducer.tar.bz2  

Apologies, I'd used an internal DNS abbreviation here that isn't global.
Replace the wrs with windriver and everything should be good.

P.
--

> 
> 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").
> 
> Upon failure, you can do <Ctrl>-<Alt>-<2> to get to a passwd-less root
> login ; there you can run dmesg and see the splat.  The image is
> currently using 4.5-rc6 ; but any kernel can be inserted; "make
> modules_install INSTALL_MOD_PATH=here" and then populating those modules
> from "here" into /lib/modules of the loopback mounted image. And of
> course updating the bzImage on the qemu cmdline.    Currently it
> contains a bzImage and modules for 4.5-rc6 as I last tested that.
> 
> Also note that vncviewer will disconnect when it goes from early boot
> 80x25 to a higer res gfx mode; just reconnect and continue observing the
> target.
> 
> I've ruled out yocto kernel changes, and yocto toolchain -- but maybe it
> is a qemu issue this commit triggers ; who knows at this point.
> 
> Since I've NFI what component(s) cause this, I wanted to have the qemu
> binary, all libraries etc as part of the reproducer and nothing left to
> chance, and I've tested the reproducer on an ancient dual core w/o vmx
> and w/o any qemu binaries installed.  Bruce also tested it on a slightly
> more modern dual socket xeon with vmx and confirmed it failed there..
> 
> Inside there is a 00-runme ; mostly a copy of qemu args the yocto
> automated tests were using.  There is also everything the qemu binaries
> need to run ; toplevel dir is noisy since qemu only looks in ./ it
> seems.  There is also an ext4.img ; as mentioned earlier, this only
> happens when uvesafb.ko is a module, so one has to loopback mount that
> image and repopulate /lib/modules/  for each boot test/bisect step.
> 
> I've also included 00-bisect.txt as the output of git bisect log.  And
> there is also 00-configs/ dir that has the ".config" kernel file for
> each build (dir names are "git describe" in here for easy correlation)
> done for the bisect (plus the latest mainline build).  The failing commit
> in the subject is v4.1-rc5-22-g9cd25aac1f44 .
> 
> My contribution here is largely a bisect that can be relied on and
> providing a portable reproducer of the regression; I am by no means a
> PAT expert ; Richard invested more time into actually understanding the
> problem than I did, so I'm going to totally throw him under the bus on
> this when it comes to considering the ultimate root cause and possible
> fixes.  :)
> 
> Paul.
> --

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

[Paul Gortmaker]

[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:
> > So, the yocto folks moved from 4.1 to 4.4 and one of their automated
> > qemu x86-32 boot tests started failing.  None of the yocto details seem
> > to matter since I offered to help and I've repropduced it using 100%
> > mainline kernels and a generic distro toolchain as well.
> > 
> > The test case is slightly complicated, in that it relies on uvesafb
> > being modular, and so one has to juggle modules within an ext4 image
> > that qemu boots from.  We tried making uvesafb builtin, but that made
> > the issue magically vanish.  Given PAT, this isn't too surprising.
> > 
> > Richard did the preliminary investigation and analysis, and from that I
> > did a bisect, and found the commit in $SUBJECT to be the root cause, as
> > per the discussion here:
> > 
> > http://lists.openembedded.org/pipermail/openembedded-core/2016-March/1183
> > 97.html
> > 
> > I'd mentioned the above to bpetkov on IRC and after confirming it was
> > still an issue on 4.5-rc6, he'd asked if I had a portable reproducer.  
> > 
> > Not sure how complicated that would be, I set out to make one from my
> > build.   With a little LD_PRELOAD type magic and ensuring all the qemu
> > components are in ./  I have one that runs on an otherwise qemu-free
> > x86-64 box. 
> > 
> > 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.

> 
> 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/118397.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:

[   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.

> 
> 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.

Thanks,
Paul.
--

> 
> Thanks!
> -Toshi

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

[Paul Gortmaker]

[Re: runtime regression with "x86/mm/pat: Emulate PAT when it is disabled"] On 04/03/2016 (Fri 15:12) Toshi Kani wrote:

> 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'

Ah, it seems for some reason your system confuses qemu from using the
"normal"  IPv4 default.   Try editing ./00-runme and add an explicit
vnc option    "-vnc 127.0.0.1:5" in front of "-show-cursor" and then:

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

...connect to localhost:5  here.  I chose 5 just to not bump into
anything your system might have on :0 or :1 already.

> 
> 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: 
> 

[snip analysis, leaving that for Richard to comment on.]

> 
> > > 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.

So I booted both with "debugpat" on the bootline; both being the last
working commit [v4.1-rc5-21-g9dac62909451]  and then the 1st failing
commit [v4.1-rc5-22-g9cd25aac1f44].  I captured the dmesg of each, then
stripped the timestamps and diffed them.


--- works.txt	2016-03-06 19:13:28.245836555 -0500
+++ fail.txt	2016-03-06 19:13:17.321836308 -0500
@@ -454,15 +454,38 @@
  8021q: 802.1Q VLAN Support v1.8
  8021q: adding VLAN 0 to HW filter on device eth0
  x86/PAT: Overlap at 0xfd000000-0xfe000000
- x86/PAT: reserve_memtype added [mem 0xfd000000-0xfdffffff], track write-combining, req write-combining, ret write-combining
- x86/PAT: Overlap at 0xfe000000-0xfe010000
- x86/PAT: reserve_memtype added [mem 0xfe000000-0xfe00ffff], track uncached-minus, req uncached-minus, ret uncached-minus
+ x86/PAT: reserve_memtype added [mem 0xfd000000-0xfdffffff], track write-combining, req uncached-minus, ret write-combining
  x86/PAT: free_memtype request [mem 0xfd000000-0xfdffffff]
- x86/PAT: free_memtype request [mem 0xfe000000-0xfe00ffff]
+ x86/PAT: Xorg:475 map pfn expected mapping type uncached-minus for [mem 0xfd000000-0xfdffffff], got write-combining
+ ------------[ cut here ]------------
+ WARNING: CPU: 0 PID: 475 at /home/paul/poky/build/tmp-glibc/work-shared/qemux86/kernel-source/arch/x86/mm/pat.c:938 untrack_pfn+0x9f/0xb0()
+ Modules linked in: 8021q parport_pc parport floppy uvesafb
+ CPU: 0 PID: 475 Comm: Xorg Not tainted 4.1.0-rc5-yocto-standard #1
+ Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.8.2-0-g33fbe13 by qemu-project.org 04/01/2014
+  00000000 00000000 cdf75db0 c1837711 00000000 cdf75de4 c104f0cb c1a39d10
+  00000000 000001db c1a38f54 000003aa c1049ddf 000003aa c1049ddf 00000000
+  c0108840 00000000 cdf75df4 c104f1a2 00000009 00000000 cdf75e18 c1049ddf
+ Call Trace:
+  [<c1837711>] dump_stack+0x4b/0x75
+  [<c104f0cb>] warn_slowpath_common+0x8b/0xc0
+  [<c1049ddf>] ? untrack_pfn+0x9f/0xb0
+  [<c1049ddf>] ? untrack_pfn+0x9f/0xb0
+  [<c104f1a2>] warn_slowpath_null+0x22/0x30
+  [<c1049ddf>] untrack_pfn+0x9f/0xb0
+  [<c104b9d3>] ? __kunmap_atomic+0x33/0xc0
+  [<c113c07f>] unmap_single_vma+0x49f/0x4b0
+  [<c113cdc3>] unmap_vmas+0x43/0x60
+  [<c11428ff>] exit_mmap+0x5f/0xf0
+  [<c1072d39>] ? get_parent_ip+0x9/0x40
+  [<c104cccd>] mmput+0x2d/0xa0
+  [<c104dfdd>] copy_process.part.45+0x10dd/0x14a0
+  [<c104e541>] do_fork+0xc1/0x390
+  [<c104e8d5>] SyS_clone+0x25/0x30
+  [<c183ef46>] syscall_call+0x7/0x7
+ ---[ end trace dbbf5a6b2dea64ff ]---
  x86/PAT: Overlap at 0xfd000000-0xfe000000
- x86/PAT: reserve_memtype added [mem 0xfd000000-0xfdffffff], track write-combining, req write-combining, ret write-combining
- x86/PAT: Overlap at 0xfe000000-0xfe010000
- x86/PAT: reserve_memtype added [mem 0xfe000000-0xfe00ffff], track uncached-minus, req uncached-minus, ret uncached-minus
+ x86/PAT: reserve_memtype added [mem 0xfd000000-0xfdffffff], track write-combining, req uncached-minus, ret write-combining
  x86/PAT: free_memtype request [mem 0xfd000000-0xfdffffff]
+ x86/PAT: Xorg:475 map pfn expected mapping type uncached-minus for [mem 0xfd000000-0xfdffffff], got write-combining
  x86/PAT: free_memtype request [mem 0xfe000000-0xfe00ffff]
- hrtimer: interrupt took 5057254 ns
+ x86/PAT: free_memtype request [mem 0xfd000000-0xfdffffff]

One obvious difference is the number of overlaps:

~$cat fail.txt |grep Overlap | wc -l
7
~$cat works.txt |grep Overlap | wc -l
9
~$

I'm assuming everyone here is used to reading diffs, but if someone
wants the full dmesg files let me know and I'll send them off-list.

Paul.