Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Andrew Morton]

(cc linuxppc-dev@lists.ozlabs.org)

On Mon, 11 Oct 2010 15:30:22 +0100
Mel Gorman <mel@csn.ul.ie> wrote:

> On Sat, Oct 09, 2010 at 04:57:18AM -0500, pacman@kosh.dhis.org wrote:
> > (What a big Cc: list... scripts/get_maintainer.pl made me do it.)
> > 
> > This will be a long story with a weak conclusion, sorry about that, but it's
> > been a long bug-hunt.
> > 
> > With recent kernels I've seen a bug that appears to corrupt random 4-byte
> > chunks of memory. It's not easy to reproduce. It seems to happen only once
> > per boot, pretty quickly after userspace has gotten started, and sometimes it
> > doesn't happen at all.
> > 
> 
> A corruption of 4 bytes could be consistent with a pointer value being
> written to an incorrect location.

It's corruption of user memory, which is unusual.  I'd be wondering if
there was a pre-existing bug which 6dda9d55bf545013597 has exposed -
previously the corruption was hitting something harmless.  Something
like a missed CPU cache writeback or invalidate operation.

How sensitive/vulnerable is PPC32 to such things?

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Mel Gorman]

On Mon, Oct 11, 2010 at 02:00:39PM -0700, Andrew Morton wrote:
> (cc linuxppc-dev@lists.ozlabs.org)
> 
> On Mon, 11 Oct 2010 15:30:22 +0100
> Mel Gorman <mel@csn.ul.ie> wrote:
> 
> > On Sat, Oct 09, 2010 at 04:57:18AM -0500, pacman@kosh.dhis.org wrote:
> > > (What a big Cc: list... scripts/get_maintainer.pl made me do it.)
> > > 
> > > This will be a long story with a weak conclusion, sorry about that, but it's
> > > been a long bug-hunt.
> > > 
> > > With recent kernels I've seen a bug that appears to corrupt random 4-byte
> > > chunks of memory. It's not easy to reproduce. It seems to happen only once
> > > per boot, pretty quickly after userspace has gotten started, and sometimes it
> > > doesn't happen at all.
> > > 
> > 
> > A corruption of 4 bytes could be consistent with a pointer value being
> > written to an incorrect location.
> 
> It's corruption of user memory, which is unusual.  I'd be wondering if
> there was a pre-existing bug which 6dda9d55bf545013597 has exposed -
> previously the corruption was hitting something harmless.  Something
> like a missed CPU cache writeback or invalidate operation.
> 

This seems somewhat plausible although it's hard to tell for sure. But
lets say we had the following situation in memory

[<----MAX_ORDER_NR_PAGES---->][<----MAX_ORDER_NR_PAGES---->]
INITRD                        memmap array

initrd gets freed and someone else very early in boot gets allocated in
there. Lets further guess that the struct pages in the memmap area are
managing the page frame where the INITRD was because it makes the situation
slightly easier to trigger. As pages get freed in the memmap array, we could
reference memory where initrd used to be but the physical memory is mapped
at two virtual addresses.

CPU A							CPU B
							Reads kernelspace virtual (gets cache line)
Writes userspace virtual (gets different cache line)
							IO, writes buffer destined for userspace (via cache line)
Cache line eviction, writeback to memory

This is somewhat contrived but I can see how it might happen even on one
CPU particularly if the L1 cache is virtual and is loose about checking
physical tags.

> How sensitive/vulnerable is PPC32 to such things?
> 

I can not tell you specifically but if the above scenario is in any way
plausible, I believe it would depend on what sort of L1 cache the CPU
has. Maybe this particular version has a virtual cache with no physical
tagging and is depending on the OS not to make virtual aliasing mistakes.

-- 
Mel Gorman
Part-time Phd Student                          Linux Technology Center
University of Limerick                         IBM Dublin Software Lab

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Mel Gorman writes:
> 
> On Mon, Oct 11, 2010 at 02:00:39PM -0700, Andrew Morton wrote:
> > 
> > It's corruption of user memory, which is unusual.  I'd be wondering if
> > there was a pre-existing bug which 6dda9d55bf545013597 has exposed -
> > previously the corruption was hitting something harmless.  Something
> > like a missed CPU cache writeback or invalidate operation.
> > 
> 
> This seems somewhat plausible although it's hard to tell for sure. But
> lets say we had the following situation in memory
> 
> [<----MAX_ORDER_NR_PAGES---->][<----MAX_ORDER_NR_PAGES---->]
> INITRD                        memmap array

I don't use initrd, so this isn't exactly what happened here. But it could be
close. Let me throw out some more information and see if it triggers any
ideas.

First, I tried a new test after seeing the corruption happen:
# md5sum /sbin/e2fsck ; echo 1 > /proc/sys/vm/drop_caches ; md5sum /sbin/e2fsck
And got 2 different answers. The second answer was the correct one.

Since applying the suggested patch which changed MAX_ORDER-1 to MAX_ORDER-2,
I've been trying to isolate exactly when the corruption happens. Since I
don't know much about kernel code, my main method is stuffing the area full
of printk's.

First I duplicated the affected function __free_one_page, since it's inlined
at 2 different places, so I could apply the patch to just one of them. This
proved that the problem is happening when called from free_one_page.

The patch which fixes (or at least covers up) the bug will only matter when
order==MAX_ORDER-2, otherwise everything is the same. So I added a lot of
printk's to show what's happening when order==MAX_ORDER-2. I found that, very
repeatably, 126 such instances occur during boot, and 61 of them pass the
page_is_buddy(higher_page, higher_buddy, order + 1) test, causing them to
call list_add_tail.

Next, since the bug appears when this code decides to call list_add_tail,
I made my own wrapper for list_add_tail, which allowed me to force some of
the calls to do list_add instead. Eventually I found that of the 61 calls,
the last one makes the difference. Allowing the first 60 calls to go through
to list_add_tail, and switching the last one to list_add, the symptom goes
away.

dump_stack() for that last call gave me a backtrace like this:
[c0303e80] [c0008124] show_stack+0x4c/0x144 (unreliable)
[c0303ec0] [c0068a84] free_one_page+0x28c/0x5b0
[c0303f20] [c0069588] __free_pages_ok+0xf8/0x120
[c0303f40] [c02d28c8] free_all_bootmem_core+0xf0/0x1f8
[c0303f70] [c02d29fc] free_all_bootmem+0x2c/0x6c
[c0303f90] [c02cc7dc] mem_init+0x70/0x2ac
[c0303fc0] [c02c66a4] start_kernel+0x150/0x27c
[c0303ff0] [00003438] 0x3438

And this might be interesting: the PFN of the page being added in that
critical 61st call is 130048, which exactly matches the number of available
pages:

  free_area_init_node: node 0, pgdat c02fee6c, node_mem_map c0330000
    DMA zone: 1024 pages used for memmap
    DMA zone: 0 pages reserved
    DMA zone: 130048 pages, LIFO batch:31
  Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 130048

Suspicious?

If 130048 is added to the head of the order==MAX_ORDER-2 free list, there's
no symptom. Add it to the tail, and the corruption appears.

That's all I know so far.

-- 
Alan Curry

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Mel Gorman]

On Wed, Oct 13, 2010 at 12:52:05PM -0500, pacman@kosh.dhis.org wrote:
> Mel Gorman writes:
> > 
> > On Mon, Oct 11, 2010 at 02:00:39PM -0700, Andrew Morton wrote:
> > > 
> > > It's corruption of user memory, which is unusual.  I'd be wondering if
> > > there was a pre-existing bug which 6dda9d55bf545013597 has exposed -
> > > previously the corruption was hitting something harmless.  Something
> > > like a missed CPU cache writeback or invalidate operation.
> > > 
> > 
> > This seems somewhat plausible although it's hard to tell for sure. But
> > lets say we had the following situation in memory
> > 
> > [<----MAX_ORDER_NR_PAGES---->][<----MAX_ORDER_NR_PAGES---->]
> > INITRD                        memmap array
> 
> I don't use initrd, so this isn't exactly what happened here. But it could be
> close. Let me throw out some more information and see if it triggers any
> ideas.
> 

Ok.

> First, I tried a new test after seeing the corruption happen:
> # md5sum /sbin/e2fsck ; echo 1 > /proc/sys/vm/drop_caches ; md5sum /sbin/e2fsck
> And got 2 different answers. The second answer was the correct one.
> 
> Since applying the suggested patch which changed MAX_ORDER-1 to MAX_ORDER-2,
> I've been trying to isolate exactly when the corruption happens. Since I
> don't know much about kernel code, my main method is stuffing the area full
> of printk's.
> 
> First I duplicated the affected function __free_one_page, since it's inlined
> at 2 different places, so I could apply the patch to just one of them. This
> proved that the problem is happening when called from free_one_page.
> 
> The patch which fixes (or at least covers up) the bug will only matter when
> order==MAX_ORDER-2, otherwise everything is the same. So I added a lot of
> printk's to show what's happening when order==MAX_ORDER-2. I found that, very
> repeatably, 126 such instances occur during boot, and 61 of them pass the
> page_is_buddy(higher_page, higher_buddy, order + 1) test, causing them to
> call list_add_tail.
> 
> Next, since the bug appears when this code decides to call list_add_tail,
> I made my own wrapper for list_add_tail, which allowed me to force some of
> the calls to do list_add instead. Eventually I found that of the 61 calls,
> the last one makes the difference. Allowing the first 60 calls to go through
> to list_add_tail, and switching the last one to list_add, the symptom goes
> away.
> 
> dump_stack() for that last call gave me a backtrace like this:
> [c0303e80] [c0008124] show_stack+0x4c/0x144 (unreliable)
> [c0303ec0] [c0068a84] free_one_page+0x28c/0x5b0
> [c0303f20] [c0069588] __free_pages_ok+0xf8/0x120
> [c0303f40] [c02d28c8] free_all_bootmem_core+0xf0/0x1f8
> [c0303f70] [c02d29fc] free_all_bootmem+0x2c/0x6c
> [c0303f90] [c02cc7dc] mem_init+0x70/0x2ac
> [c0303fc0] [c02c66a4] start_kernel+0x150/0x27c
> [c0303ff0] [00003438] 0x3438
> 
> And this might be interesting: the PFN of the page being added in that
> critical 61st call is 130048, which exactly matches the number of available
> pages:
> 
>   free_area_init_node: node 0, pgdat c02fee6c, node_mem_map c0330000
>     DMA zone: 1024 pages used for memmap
>     DMA zone: 0 pages reserved
>     DMA zone: 130048 pages, LIFO batch:31
>   Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 130048
> 
> Suspicious?
> 

A bit but I still don't know why it would cause corruption. Maybe this is still
a caching issue but the difference in timing between list_add and list_add_tail
is enough to hide the bug. It's also possible there are some registers
ioremapped after the memmap array and reading them is causing some
problem.

Andrew, what is the right thing to do here? We could flail around looking
for explanations as to why the bug causes a user buffer corruption but never
get an answer or do we go with this patch, preferably before 2.6.36 releases?

==== CUT HERE ====
mm, page-allocator: Do not check the state of a non-existant buddy during free

There is a bug in commit [6dda9d55: page allocator: reduce fragmentation
in buddy allocator by adding buddies that are merging to the tail of the
free lists] that means a buddy at order MAX_ORDER is checked for
merging. A page of this order never exists so at times, an effectively
random piece of memory is being checked.

Alan Curry has reported that this is causing memory corruption in userspace
data on a PPC32 platform (http://lkml.org/lkml/2010/10/9/32). It is not clear
why this is happening. It could be a cache coherency problem where pages
mapped in both user and kernel space are getting different cache lines due
to the bad read from kernel space (http://lkml.org/lkml/2010/10/13/179). It
could also be that there are some special registers being io-remapped at
the end of the memmap array and that a read has special meaning on them.
Compiler bugs have been ruled out because the assembly before and after
the patch looks relatively harmless.

This patch fixes the problem by ensuring we are not reading a possibly
invalid location of memory. It's not clear why the read causes
corruption but one way or the other it is a buggy read.

Signed-off-by: Mel Gorman <mel@csn.ul.ie>
---
 mm/page_alloc.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/mm/page_alloc.c b/mm/page_alloc.c
index a8cfa9c..93cef41 100644
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -530,7 +530,7 @@ static inline void __free_one_page(struct page *page,
 	 * so it's less likely to be used soon and more likely to be merged
 	 * as a higher order page
 	 */
-	if ((order < MAX_ORDER-1) && pfn_valid_within(page_to_pfn(buddy))) {
+	if ((order < MAX_ORDER-2) && pfn_valid_within(page_to_pfn(buddy))) {
 		struct page *higher_page, *higher_buddy;
 		combined_idx = __find_combined_index(page_idx, order);
 		higher_page = page + combined_idx - page_idx;

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Mel Gorman writes:
> 
> A bit but I still don't know why it would cause corruption. Maybe this is still
> a caching issue but the difference in timing between list_add and list_add_tail
> is enough to hide the bug. It's also possible there are some registers
> ioremapped after the memmap array and reading them is causing some
> problem.

I've been doing a lot more tests and I'm sure that 6dda9d55 is not really
responsible. It just happens to provoke the bug in my particular setup.
Whatever it is, it's very sensitive to small changes.

At the end of free_all_bootmem, the free list for order 9 has 4 entries.
Which one is at the head of the list depends on whether 6dda9d55 is applied
or not. If page number 130048 is at the head of the list, it gets used fairly
soon, and everything's fine. The alternative is that page number 64512 is at
the head of the list, so it gets used fairly soon, and corruption occurs.

> 
> Andrew, what is the right thing to do here? We could flail around looking
> for explanations as to why the bug causes a user buffer corruption but never
> get an answer or do we go with this patch, preferably before 2.6.36 releases?

I've been flailing around quite a bit. Here's my latest result:

Since I can view the corruption with md5sum /sbin/e2fsck, I know it's in a
clean cached page. So I made an extra copy of /sbin/e2fsck, which won't be
loaded into memory during boot. So now after the corruption happens, I can
  cmp -l /sbin/e2fsck good-e2fsck
for a quick look at the changed bytes. Much easier than provoking a segfault
under gdb.

Then I got really creative and wrote a cmp replacement which mmaps the files
and reports the physical addresses from /proc/self/pagemap of the pages that
don't match. And the consistent result is that physical pages 64604 and 64609
(both in the range of the order=9 64512) have wrong contents. And the
corruption is always a single word 128 bytes after the start of the page.
Physical addresses 0x0fc5c080 and 0x0fc61080 are hit every time.

The values of the corrupted words, observed in 5 consecutive boots, were:
  at 0fc5c080   at 0fc61080
  -----------   -----------
  c3540000      92510000
  565c0000      23590000
  c85b0000      97580000
  d15f0000      9e5c0000
  d95b0000      a8580000

The low 16 bits are all 0 and the upper 16 bits seem randomly distributed.
But look at the differences:

  c3540000 - 92510000 = 31030000
  565c0000 - 23590000 = 33030000
  c85b0000 - 97580000 = 31030000
  d15f0000 - 9e5c0000 = 33030000
  d95b0000 - a8580000 = 31030000

This means something... but I don't know what.

In a completely different method of investigation, I went back a few stable
kernels, got 2.6.33.7 and applied 6dda9d55 to it, thinking that if 6dda9d55
only reveals a pre-existing bug, I could bisect it using 6dda9d55 as a
bug-revealing assistant. The bug appeared when running 2.6.33.7 with 6dda9d55
applied. That was discouraging.

>This patch fixes the problem by ensuring we are not reading a possibly
>invalid location of memory. It's not clear why the read causes
>corruption but one way or the other it is a buggy read.

At least that part of the explanation is wrong. Where's the buggy read?
The action taken by the 6dda9d55 version of __free_one_page looks perfectly
legitimate to me. Page numbers:

[129024       ] [130048       ]   order=10
[129024 129536] [130048 130560]   order=9

130048 is being freed. 130560 is not free. 129024 (the higher_buddy) is
already free at order=10. So 130048 is being pushed to the tail of the free
list, on the speculation that 130560 might soon be free and then the whole
thing will form an order=11 free page, the only problem being that order=11
is too high so that later merge will never happen. It's not useful, and maybe
not conceptually valid to say that 129024 is the buddy of 130048, but it is
an existing page, and the only way it wouldn't be is if the total memory size
was not a multiple of 1<<(MAX_ORDER-1) pages

-- 
Alan Curry

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Mon, 2010-10-18 at 14:10 -0500, pacman@kosh.dhis.org wrote:

> I've been flailing around quite a bit. Here's my latest result:
> 
> Since I can view the corruption with md5sum /sbin/e2fsck, I know it's in a
> clean cached page. So I made an extra copy of /sbin/e2fsck, which won't be
> loaded into memory during boot. So now after the corruption happens, I can
>   cmp -l /sbin/e2fsck good-e2fsck
> for a quick look at the changed bytes. Much easier than provoking a segfault
> under gdb.
> 
> Then I got really creative and wrote a cmp replacement which mmaps the files
> and reports the physical addresses from /proc/self/pagemap of the pages that
> don't match. And the consistent result is that physical pages 64604 and 64609
> (both in the range of the order=9 64512) have wrong contents. And the
> corruption is always a single word 128 bytes after the start of the page.
> Physical addresses 0x0fc5c080 and 0x0fc61080 are hit every time.

 .../...

You can do something fun... like a timer interrupt that peeks at those
physical addresses from the linear mapping for example, and try to find
out "when" they get set to the wrong value (you should observe the load
from disk, then the corruption, unless they end up being loaded
incorrectly (ie. dma coherency problem ?) ...

>From there, you might be able to close onto the culprit a bit more, for
example, try using the DABR register to set data access breakpoints
shortly before the corruption spot. AFAIK, On those old 32-bit CPUs, you
can set whether you want it to break on a real or a virtual address.

You can also sprinkle tests for the page content through the code if
that doesn't work to try to "close in" on the culprit (for example if
it's a case of stray DMA, like a network driver bug or such).

Cheers,
Ben.


> The values of the corrupted words, observed in 5 consecutive boots, were:
>   at 0fc5c080   at 0fc61080
>   -----------   -----------
>   c3540000      92510000
>   565c0000      23590000
>   c85b0000      97580000
>   d15f0000      9e5c0000
>   d95b0000      a8580000
> 
> The low 16 bits are all 0 and the upper 16 bits seem randomly distributed.
> But look at the differences:
> 
>   c3540000 - 92510000 = 31030000
>   565c0000 - 23590000 = 33030000
>   c85b0000 - 97580000 = 31030000
>   d15f0000 - 9e5c0000 = 33030000
>   d95b0000 - a8580000 = 31030000
> 
> This means something... but I don't know what.
> 
> In a completely different method of investigation, I went back a few stable
> kernels, got 2.6.33.7 and applied 6dda9d55 to it, thinking that if 6dda9d55
> only reveals a pre-existing bug, I could bisect it using 6dda9d55 as a
> bug-revealing assistant. The bug appeared when running 2.6.33.7 with 6dda9d55
> applied. That was discouraging.
> 
> >This patch fixes the problem by ensuring we are not reading a possibly
> >invalid location of memory. It's not clear why the read causes
> >corruption but one way or the other it is a buggy read.
> 
> At least that part of the explanation is wrong. Where's the buggy read?
> The action taken by the 6dda9d55 version of __free_one_page looks perfectly
> legitimate to me. Page numbers:
> 
> [129024       ] [130048       ]   order=10
> [129024 129536] [130048 130560]   order=9
> 
> 130048 is being freed. 130560 is not free. 129024 (the higher_buddy) is
> already free at order=10. So 130048 is being pushed to the tail of the free
> list, on the speculation that 130560 might soon be free and then the whole
> thing will form an order=11 free page, the only problem being that order=11
> is too high so that later merge will never happen. It's not useful, and maybe
> not conceptually valid to say that 129024 is the buddy of 130048, but it is
> an existing page, and the only way it wouldn't be is if the total memory size
> was not a multiple of 1<<(MAX_ORDER-1) pages
> 
> -- 
> Alan Curry
> _______________________________________________
> Linuxppc-dev mailing list
> Linuxppc-dev@lists.ozlabs.org
> https://lists.ozlabs.org/listinfo/linuxppc-dev

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Benjamin Herrenschmidt writes:
> 
> You can do something fun... like a timer interrupt that peeks at those
> physical addresses from the linear mapping for example, and try to find
> out "when" they get set to the wrong value (you should observe the load
> from disk, then the corruption, unless they end up being loaded
> incorrectly (ie. dma coherency problem ?) ...

I'm headed toward something like that. Maybe not a timer, maybe a "check it
every time the kernel is entered". But first I have to work out exactly when
the disk load completes so I know when to start checking.

> 
> >From there, you might be able to close onto the culprit a bit more, for
> example, try using the DABR register to set data access breakpoints
> shortly before the corruption spot. AFAIK, On those old 32-bit CPUs, you
> can set whether you want it to break on a real or a virtual address.

I thought of that, but as far as I can tell, this CPU doesn't have DABR.
/proc/cpuinfo
processor	: 0
cpu		: 7447/7457
clock		: 999.999990MHz
revision	: 1.1 (pvr 8002 0101)
bogomips	: 66.66
timebase	: 33333333
platform	: CHRP
model		: Pegasos2
machine		: CHRP Pegasos2
Memory		: 512 MB

My next thought was: right after the correct value appears in memory, unmap
the page from the kernel and let it Oops when it tries to write there. Then I
found out that the kernel is using BATs instead of page tables for its own
view of memory. Booting with "nobats" completely changes the memory usage
pattern (probably because it's allocating a lot of pages to hold PTEs that it
didn't need before)

> 
> You can also sprinkle tests for the page content through the code if
> that doesn't work to try to "close in" on the culprit (for example if
> it's a case of stray DMA, like a network driver bug or such).

No network drivers are loaded when this happens.

-- 
Alan Curry

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

> > >From there, you might be able to close onto the culprit a bit more, for
> > example, try using the DABR register to set data access breakpoints
> > shortly before the corruption spot. AFAIK, On those old 32-bit CPUs, you
> > can set whether you want it to break on a real or a virtual address.
> 
> I thought of that, but as far as I can tell, this CPU doesn't have DABR.
> /proc/cpuinfo
> processor	: 0
> cpu		: 7447/7457
> clock		: 999.999990MHz
> revision	: 1.1 (pvr 8002 0101)
> bogomips	: 66.66
> timebase	: 33333333
> platform	: CHRP
> model		: Pegasos2
> machine		: CHRP Pegasos2
> Memory		: 512 MB

AFAIK, the 7447 is just a derivative of the 7450 design which -does-
have a DABR ... Unless it's broken :-)

> My next thought was: right after the correct value appears in memory, unmap
> the page from the kernel and let it Oops when it tries to write there. Then I
> found out that the kernel is using BATs instead of page tables for its own
> view of memory. Booting with "nobats" completely changes the memory usage
> pattern (probably because it's allocating a lot of pages to hold PTEs that it
> didn't need before)

Right. And that hides the problem I suppose ?

> > You can also sprinkle tests for the page content through the code if
> > that doesn't work to try to "close in" on the culprit (for example if
> > it's a case of stray DMA, like a network driver bug or such).
> 
> No network drivers are loaded when this happens.

Ok.

Cheers,
Ben.

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Benjamin Herrenschmidt writes:
> > 
> > I thought of that, but as far as I can tell, this CPU doesn't have DABR.
> 
> AFAIK, the 7447 is just a derivative of the 7450 design which -does-
> have a DABR ... Unless it's broken :-)

Hmm. gdb resorts to single-stepping when I set a watchpoint while debugging
some userspace program, which I assumed was caused by lack of hardware
watchpoint support. But that's not important right now.

I made a new discovery. During a test boot while looking at the usual symptom
of a corrupted page cache, I run md5sum /sbin/e2fsck twice and got 2
different results, neither one of them correct. The third time, yet another
different result. A few dozen more times, a few dozen more unique results. I
had somehow managed to get a usable interactive shell while corruption was
ongoing.

So then I ran
  dd if=/dev/mem bs=4 count=1 skip=$((0xfc5c080/4)) | od -t x4
a few times very fast, plucking the first affected word directly out of
memory by its physical address. The result:

The low 16 bits are always zero as before. The high 16 bits are a counter,
being incremented at about 1000Hz (as close as I could measure with a crude
shell script. 1024Hz would also be within the margin of error). And it's
little-endian.

While I was watching this happen, there were only 5 or 6 userspace processes
running, and 3 of them were shells. So I doubt that anything in userspace was
doing it. It went on for a few minutes before I exited the interactive shell
and allowed the boot to continue, while keeping an extra shell running on
tty2 to continue making observations. It stopped incrementing almost
immediately.

So what type of driver, firmware, or hardware bug puts a 16-bit 1000Hz timer
in memory, and does it in little-endian instead of the CPU's native byte
order? And why does it stop doing it some time during the early init scripts,
shortly after the root filesystem fsck?

I have not yet attempted to repeat the experiment. If it is repeatable, I'll
probe more deeply into those init scripts later. I'm looking hard at
/etc/rcS.d/S11hwclock.sh

-- 
Alan Curry

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Segher Boessenkool]

> I made a new discovery.

And this nails it :-)

> So then I ran
>   dd if=/dev/mem bs=4 count=1 skip=$((0xfc5c080/4)) | od -t x4
> a few times very fast, plucking the first affected word directly out of
> memory by its physical address. The result:
>
> The low 16 bits are always zero as before. The high 16 bits are a counter,
> being incremented at about 1000Hz (as close as I could measure with a
> crude
> shell script. 1024Hz would also be within the margin of error). And it's
> little-endian.

> So what type of driver, firmware, or hardware bug puts a 16-bit 1000Hz
> timer
> in memory, and does it in little-endian instead of the CPU's native byte
> order? And why does it stop doing it some time during the early init
> scripts,
> shortly after the root filesystem fsck?

It looks like it is the frame counter in an USB OHCI HCCA.
16-bit, 1kHz update, offset x'80 in a page.

So either the kernel forgot to call quiesce on it, or the firmware
doesn't implement that, or the firmware messed up some other way.


Segher

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Tue, 2010-10-19 at 22:47 +0200, Segher Boessenkool wrote:
> 
> It looks like it is the frame counter in an USB OHCI HCCA.
> 16-bit, 1kHz update, offset x'80 in a page.
> 
> So either the kernel forgot to call quiesce on it, or the firmware
> doesn't implement that, or the firmware messed up some other way.

I vote for the FW being on crack. Wouldn't be the first time with
Pegasos.

It's an OHCI or an UHCI in there ?

Can you try in prom_init.c changing the prom_close_stdin() function to
also close "stdout" ? 

         if (prom_getprop(_prom->chosen, "stdin", &val, sizeof(val)) > 0)
                 call_prom("close", 1, 0, val);
+        if (prom_getprop(_prom->chosen, "stdout", &val, sizeof(val)) > 0)
+               call_prom("close", 1, 0, val);

See if that makes a difference ?

Last option would be to manually turn the thing off with MMIO in yet-another
pegasos workaround in prom_init.c.

Cheers,
Ben.

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Benjamin Herrenschmidt writes:
> 
> On Tue, 2010-10-19 at 22:47 +0200, Segher Boessenkool wrote:
> > 
> > It looks like it is the frame counter in an USB OHCI HCCA.
> > 16-bit, 1kHz update, offset x'80 in a page.
> > 
> > So either the kernel forgot to call quiesce on it, or the firmware
> > doesn't implement that, or the firmware messed up some other way.
> 
> I vote for the FW being on crack. Wouldn't be the first time with
> Pegasos.
> 
> It's an OHCI or an UHCI in there ?

There's one of each... UHCI on the motherboard, OHCI on a card in a PCI
expansion slot. They shipped the ODW with the extra controller on an
expansion card since the on-board UHCI doesn't do USB2.0.

And that OHCI controller does appear to be the culprit. The 2 affected
addresses tick at 1000Hz until ohci-hcd is modprobe'd, then they stop.

I think the mm people can consider this closed. 6dda9d55 didn't do anything
but expose a problem which has been here all along. Will drop them from Cc
list in any further messages.

> 
> Can you try in prom_init.c changing the prom_close_stdin() function to
> also close "stdout" ? 
> 
>          if (prom_getprop(_prom->chosen, "stdin", &val, sizeof(val)) > 0)
>                  call_prom("close", 1, 0, val);
> +        if (prom_getprop(_prom->chosen, "stdout", &val, sizeof(val)) > 0)
> +               call_prom("close", 1, 0, val);
> 
> See if that makes a difference ?

Huge difference. With no stdout to print to, the kernel seems to freeze up.
Or at least it loses the console. The last message it prints is "Device tree
struct 0x00933000 -> 0x00957000" then there's just nothing. I waited a while
for the console to come on but it didn't.

The diff fragment above applied inside prom_close_stdin, but there are some
prom_printf calls after prom_close_stdin. Calling prom_printf after closing
stdout sounds like it could be bad. If I moved it down below all the
prom_printf's, it would be after the "quiesce" call. Would that be acceptable
(or even interesting as an experiment)? Does a close need a quiesce after it?

-- 
Alan Curry

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Tue, 2010-10-19 at 22:23 -0500, pacman@kosh.dhis.org wrote:
> The diff fragment above applied inside prom_close_stdin, but there are
> some
> prom_printf calls after prom_close_stdin. Calling prom_printf after
> closing
> stdout sounds like it could be bad. If I moved it down below all the
> prom_printf's, it would be after the "quiesce" call. Would that be
> acceptable
> (or even interesting as an experiment)? Does a close need a quiesce
> after it?

Just try :-) "quiesce" is something that afaik only apple ever
implemented anyways. It uses hooks inside their OF to shut down all
drivers that do bus master (among other HW sanitization tasks).

Cheers,
Ben.

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Benjamin Herrenschmidt writes:
> 
> On Tue, 2010-10-19 at 22:23 -0500, pacman@kosh.dhis.org wrote:
> > The diff fragment above applied inside prom_close_stdin, but there are
> > some
> > prom_printf calls after prom_close_stdin. Calling prom_printf after
> > closing
> > stdout sounds like it could be bad. If I moved it down below all the
> > prom_printf's, it would be after the "quiesce" call. Would that be
> > acceptable
> > (or even interesting as an experiment)? Does a close need a quiesce
> > after it?
> 
> Just try :-) "quiesce" is something that afaik only apple ever
> implemented anyways. It uses hooks inside their OF to shut down all
> drivers that do bus master (among other HW sanitization tasks).

I booted a version with a prom_close_stdout after the last prom_debug. It
didn't have any effect. That 1000Hz clock was still ticking.

-- 
Alan Curry

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Wed, 2010-10-20 at 13:33 -0500, pacman@kosh.dhis.org wrote:
> > Just try :-) "quiesce" is something that afaik only apple ever
> > implemented anyways. It uses hooks inside their OF to shut down all
> > drivers that do bus master (among other HW sanitization tasks).
> 
> I booted a version with a prom_close_stdout after the last prom_debug. It
> didn't have any effect. That 1000Hz clock was still ticking. 

Ok so you'll have to make up a "workaround" in prom_init that looks for
OHCI's in the device-tree and disable them.

Check if the OHCI node has some existing f-code words you can use for
that with "dev /path-to-ohci words" in OF for example. If not, you may
need to use the low level register accessors. Use OF client interface
"interpret" to run forth code from C.

Cheers,
Ben.

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[pacman]

Benjamin Herrenschmidt writes:
> 
> On Wed, 2010-10-20 at 13:33 -0500, pacman@kosh.dhis.org wrote:
> > > Just try :-) "quiesce" is something that afaik only apple ever
> > > implemented anyways. It uses hooks inside their OF to shut down all
> > > drivers that do bus master (among other HW sanitization tasks).
> > 
> > I booted a version with a prom_close_stdout after the last prom_debug. It
> > didn't have any effect. That 1000Hz clock was still ticking. 
> 
> Ok so you'll have to make up a "workaround" in prom_init that looks for
> OHCI's in the device-tree and disable them.

I'm a long way from understanding how to do that.

> 
> Check if the OHCI node has some existing f-code words you can use for
> that with "dev /path-to-ohci words" in OF for example. If not, you may

Nothing there but open close decode-unit encode-unit

> need to use the low level register accessors. Use OF client interface
> "interpret" to run forth code from C.

Here are the major problems:

1. How do I locate all usb nodes in the device tree?

2. How do I know if a particular usb node is OHCI?

3. Knowing that a node is OHCI, how do I know where its control registers
are? I'm sure this is calculated from the "reg" property but I don't see how.

4. Knowing where the control registers are, how do I access them? Do I need
to request a virt-to-phys mapping or can I assume that it's already mapped,
or that the "rl!" command will do the right thing with a physical address?

5. Which control register should I use to tell the OHCI to be quiet? Just do
a general reset, or is there something that specifically turns off the
counter that's been causing the trouble?

-- 
Alan Curry

Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55)

[pacman]

Benjamin Herrenschmidt writes:
> 
> Ok so you'll have to make up a "workaround" in prom_init that looks for
> OHCI's in the device-tree and disable them.
> 
> Check if the OHCI node has some existing f-code words you can use for
> that with "dev /path-to-ohci words" in OF for example. If not, you may
> need to use the low level register accessors. Use OF client interface
> "interpret" to run forth code from C.

I responded with a long list of reasons that I'm not qualified to do that
work myself:
|Here are the major problems:
|
|1. How do I locate all usb nodes in the device tree?
|
|2. How do I know if a particular usb node is OHCI?
|
|3. Knowing that a node is OHCI, how do I know where its control registers
|are? I'm sure this is calculated from the "reg" property but I don't see how.
|
|4. Knowing where the control registers are, how do I access them? Do I need
|to request a virt-to-phys mapping or can I assume that it's already mapped,
|or that the "rl!" command will do the right thing with a physical address?
|
|5. Which control register should I use to tell the OHCI to be quiet? Just do
|a general reset, or is there something that specifically turns off the
|counter that's been causing the trouble?

Since then, the silence has been deafening.

My assumption now is that this is not ever getting fixed. I'm certainly not
able to fix it. I'm not a even kernel programmer! I got far enough to
diagnose the cause just with the "add more printk's and boot it again"
technique. Hundreds of reboots trying to figure it out. I was a conscientious
bug-reporter, I thought.

I could pull the PCI card and be done with it. I never used those USB ports
anyway. But after all the suffering I went through to find this bug... the
crashing e2fsck's and consequent filesystem corruption... I hate the idea of
surrendering to it. There are possibly other affected users who I'd be
abandoning to suffer similarly in the future.

For the last week I've studied OpenFirmware as hard as I can. I read the spec
cover to cover. And the USB annex, and the PCI annex. But I'm still lost in
all the different address formats.

I took my best guess on how to handle this problem, and ran with it, ending
up with a 97-line Forth script, and that was just to get a virtual address,
not to actually do anything with it, and it used a hardcoded device path. But
it didn't work, all I got was an "invalid pointer" error. I made another
guess at something that wasn't documented anywhere (the fact that this stuff
is insufficiently documented is the one thing I can state with complete
confidence!) and out came a successful translation to a virtual address: 0.

If I'm the only one fighting this bug, the bug wins.

-- 
Alan Curry

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55)

[Olaf Hering]

On Wed, Oct 27, pacman@kosh.dhis.org wrote:

> |1. How do I locate all usb nodes in the device tree?
> |
> |2. How do I know if a particular usb node is OHCI?

In the installed system, run 'lspci | grep -i usb', this gives the pci
bus numbers.  Then run 'find /sys -name devspec', and look or the bus
numbers from the lspci output.  Each devspec file contains the firmware
path.  The ohci node may have subdirectories. Run 'words' in each of
them at the firmware prompt. Perhaps there is one to shutdown the
controller?

I just noticed older firmware did not have a node for ohci, newer ones
my have a /pci@80000000/usb@5 node.

Good luck.

Olaf

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[pacman]

Olaf Hering writes:
> 
> On Wed, Oct 27, pacman@kosh.dhis.org wrote:
> 
> > |1. How do I locate all usb nodes in the device tree?
> > |
> > |2. How do I know if a particular usb node is OHCI?
> 
> In the installed system, run 'lspci | grep -i usb', this gives the pci
> bus numbers.  Then run 'find /sys -name devspec', and look or the bus

Once the system is running, I have no problem figuring it out. What I meant
was how do I write some code to identify OHCI devices correctly, from within
the limited environment of the Forth interpreter, which will work in the
general case.

I already know that /pci@80000000/usb@5 and /pci@80000000/usb@5,1 are the
problem nodes on my machine. And I've learned enough about OF to do a full
recursive device tree search to find the USB nodes, so the first question is
answered.

But the UHCI and OHCI nodes look very much alike in the OF properties. "name"
is just "usb" and there's no "compatible".

The big question that I'm still stumbling over is how to access the device
registers. The "reg" property looks like this:
             phys                 size
 -------------------------- -----------------
 00002800 00000000 00000000 00000000 00000000
 02002810 00000000 00000000 00000000 00001000
so I take the second group of 5 words, which should be the device registers,
and try to map it to a virtual address. The members are unpacked on the stack
like this:
  00000000 00000000 02002810 00000000 00001000
which looks like this stack diagram from OF spec:
  map-in ( phys.lo ... phys.hi size -- virt )
and the method call goes like this:
  " map-in" $call-parent
The result: "invalid pointer". But I notice it only popped 4 items. I think
maybe the "size" for map-in is not the same as the "size" found in the reg
property. Maybe #size-cells applies in one place but not the other. Thanks
for not documenting that! Try again:
  00000000 00000000 02002810 00001000 " map-in" $call-parent
This one doesn't complain, but leaves me a 0 on the stack as its answer. The
OHCI registers have been mapped to virtual address 0? Doesn't seem likely.

-- 
Alan Curry

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[Segher Boessenkool]

>> > |1. How do I locate all usb nodes in the device tree?
>> > |
>> > |2. How do I know if a particular usb node is OHCI?

You look for compatible "usb-ohci".

But this doesn't help you.  You do not know yet if the
problem happens for all usb-ohci; for example, it could be
that you have the console output device on usb; or as another
example, it could be that this firmware leaves all pci devices
in some active state.

So as I see it you have only two options:

1) Figure out what exactly is going on;
or 2) make the kernel shut down all pci devices early (either
in actual kernel code, or in an OF boot script).

> The big question that I'm still stumbling over is how to access the device
> registers. The "reg" property looks like this:

You should look at "assigned-addresses", not "reg".  Well,
you first need to look at "reg" to figure out what entry
in "assigned-addresses" to use.


Segher

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[pacman]

Segher Boessenkool writes:
> 
> >> > |1. How do I locate all usb nodes in the device tree?
> >> > |
> >> > |2. How do I know if a particular usb node is OHCI?
> 
> You look for compatible "usb-ohci".

There is no "compatible" there. I can probably use class-code since the
parent is a PCI bus.

> 
> But this doesn't help you.  You do not know yet if the
> problem happens for all usb-ohci; for example, it could be
> that you have the console output device on usb; or as another
> example, it could be that this firmware leaves all pci devices
> in some active state.
> 
> So as I see it you have only two options:
> 
> 1) Figure out what exactly is going on;

I thought we were past that. The startup sequence leaves the device in a bad
state (writing 1000 times per second to memory that the kernel believes is
not in use), so it needs to be given a reset command before the kernel tries
to use that memory.

> > The big question that I'm still stumbling over is how to access the device
> > registers. The "reg" property looks like this:
> 
> You should look at "assigned-addresses", not "reg".  Well,
> you first need to look at "reg" to figure out what entry
> in "assigned-addresses" to use.

The properties look like this:

/pci@80000000/usb@5/assigned-addresses
 02002810 00000000 80000000 00000000 00001000
/pci@80000000/usb@5/reg
 00002800 00000000 00000000 00000000 00000000
 02002810 00000000 00000000 00000000 00001000

I'm not sure how I'm supposed to know which entry from "reg" is the right
one. I've been guessing that it's the second one, since that one matches the
only entry in "assigned-addresses". It's supposed to go the other direction?

-- 
Alan Curry

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[Segher Boessenkool]

>> 1) Figure out what exactly is going on;
>
> I thought we were past that.

We are not.

> The startup sequence leaves the device in a
> bad
> state (writing 1000 times per second to memory that the kernel believes is
> not in use), so it needs to be given a reset command before the kernel
> tries
> to use that memory.

The question now is what causes the firmware to do that, and then
what is the best way to stop it from doing that.

>> > The big question that I'm still stumbling over is how to access the
>> device
>> > registers. The "reg" property looks like this:
>>
>> You should look at "assigned-addresses", not "reg".  Well,
>> you first need to look at "reg" to figure out what entry
>> in "assigned-addresses" to use.

Ignore this part, I was confused.

> The properties look like this:
>
> /pci@80000000/usb@5/assigned-addresses
>  02002810 00000000 80000000 00000000 00001000

Lovely, incorrect data (it should start with 82002810, i.e.,
not relocatable -- it is already an assigned address!).

This means: 32-bit MMIO address space for bus 0 dev 5 fn 0,
first BAR; assigned to address 80000000; size is 1000.

You could try a boot script like this:


dev /pci
0 ffff04 DO 0 i config-w! -100 +LOOP
device-end


which should disable all PCI devices on all busses, on that
PCI host bus (it disables every device behind pci-pci bridges
separately, as long as every such bridge has a higher secondary
bus number than primary bus number; if you only want to disable
everything on the root bus (which should be sufficient), use
ff04 instead of ffff04).


Segher

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[pacman]

Segher Boessenkool writes:
> 
> >> 1) Figure out what exactly is going on;
> >
> > I thought we were past that.
> 
> We are not.
> 
> > The startup sequence leaves the device in a
> > bad
> > state (writing 1000 times per second to memory that the kernel believes is
> > not in use), so it needs to be given a reset command before the kernel
> > tries
> > to use that memory.
> 
> The question now is what causes the firmware to do that, and then
> what is the best way to stop it from doing that.

As far as I can tell, it turns on the host controller during the global
probe, which is not wrong because USB devices could theoretically be used for
booting, or for console display. Then it never turns off the host controller
because someone forgot to put in the code to turn it off.

It's not easy to figure out exactly where that should have been done. Turning
off the host controller too soon would rule out booting from USB, but leaving
it running while the OS is starting up has caused a major problem.

So is it wrong to leave the host controller enabled when the OS is booted? If
not, then the error must be in the communication of which memory addresses
are in use by OF. I've got a node /memory@0 whose "available" property looks
like this:
 00000000 00400000
 00584000 0007c000
 0092a1d8 00004e28
 00a2f000 005d1000
 01800000 0e3fd000
 0fbffab4 0000054c
>From that list, it looks to me like OF is telling the kernel that it should
not attempt to use any address above 0xfbffab4+0x54c == 0xfc00000. The
addresses being written to by the OHCI controller are 0xfc5c080 and
0xfc61080. If the kernel is staying within the "available" list, there won't
be a problem.

Later, when the kernel decides it's done using OF, what's supposed to happen?
It closes stdin, but that doesn't help here since the offending device is a
bus node, not an input node. It looks to me like the kernel makes the
assumption that all devices other than stdin and stdout will have been
deactivated already when the kernel starts, and that this assumption has
been violated. Who is wrong, from the perspective of the OF standard, the
assumer or the violator?

Then there's the "quiesce" call, which I don't understand at all since it's
not mentioned in any of the specification documents I've been able to find.
It's been mentioned as an Apple-only thing. Seems like it would be a good
name for a "make all the devices stop puking on the RAM" function. Since the
OF spec doesn't include this function, they must not have thought it was
necessary.

> > /pci@80000000/usb@5/assigned-addresses
> >  02002810 00000000 80000000 00000000 00001000
> 
> Lovely, incorrect data (it should start with 82002810, i.e.,
> not relocatable -- it is already an assigned address!).

Now you see how I have trouble relating the docs to the reality...

> 
> This means: 32-bit MMIO address space for bus 0 dev 5 fn 0,
> first BAR; assigned to address 80000000; size is 1000.

But "address 80000000" is a physical address (I think), so do I need to do a
map-in on it before using it?

> 
> You could try a boot script like this:
> 
> 
> dev /pci
> 0 ffff04 DO 0 i config-w! -100 +LOOP
> device-end
> 
> 
> which should disable all PCI devices on all busses, on that

Almost all of my devices are under that PCI node. What will I prove by
disabling them?

-- 
Alan Curry

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[Segher Boessenkool]

> So is it wrong to leave the host controller enabled when the OS is booted?

Yes.  Or, rather, there should be some way for the client to turn off
all dma and interrupt activity; if the client closes the ihandles in
"/chosen", and perhaps calls "quiesce", that should be enough.



> If
> not, then the error must be in the communication of which memory addresses
> are in use by OF. I've got a node /memory@0 whose "available" property
> looks
> like this:
>  00000000 00400000
>  00584000 0007c000
>  0092a1d8 00004e28
>  00a2f000 005d1000
>  01800000 0e3fd000
>  0fbffab4 0000054c
>>From that list, it looks to me like OF is telling the kernel that it
>> should
> not attempt to use any address above 0xfbffab4+0x54c == 0xfc00000.

The client is allowed to "take over" all memory, if it doesn't call OF
after doing so.  This won't work if some device scribbles on it, as
you have seen.

> Later, when the kernel decides it's done using OF, what's supposed to
> happen?
> It closes stdin, but that doesn't help here since the offending device is
> a
> bus node, not an input node. It looks to me like the kernel makes the
> assumption that all devices other than stdin and stdout will have been
> deactivated already when the kernel starts, and that this assumption has
> been violated. Who is wrong, from the perspective of the OF standard, the
> assumer or the violator?

The violator.

>> Lovely, incorrect data (it should start with 82002810, i.e.,
>> not relocatable -- it is already an assigned address!).
>
> Now you see how I have trouble relating the docs to the reality...

Yeah :-(

>> This means: 32-bit MMIO address space for bus 0 dev 5 fn 0,
>> first BAR; assigned to address 80000000; size is 1000.
>
> But "address 80000000" is a physical address (I think), so do I need to do
> a
> map-in on it before using it?

Yes.

>> You could try a boot script like this:
>>
>>
>> dev /pci
>> 0 ffff04 DO 0 i config-w! -100 +LOOP
>> device-end
>>
>>
>> which should disable all PCI devices on all busses, on that
>
> Almost all of my devices are under that PCI node. What will I prove by
> disabling them?

You should put it after "load", and before "go".

It should give you a working system; it's a sledgehammer workaround.


Segher

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[pacman]

Segher Boessenkool writes:
> 
> > So is it wrong to leave the host controller enabled when the OS is booted?
> 
> Yes.  Or, rather, there should be some way for the client to turn off
> all dma and interrupt activity; if the client closes the ihandles in
> "/chosen", and perhaps calls "quiesce", that should be enough.

Sounds good to me, I only wish someone had written down what "quiesce" means.

> >
> > Almost all of my devices are under that PCI node. What will I prove by
> > disabling them?
> 
> You should put it after "load", and before "go".
> 
> It should give you a working system; it's a sledgehammer workaround.

I can do it a little more gracefully than that. This works to deactivate the
problem devices manually:

  1 lbflip 80000000 8 + rl!
  1 lbflip 80001000 8 + rl!

where 80000000 and 80001000 have been obtained from
/pci@80000000/usb@5/assigned-addresses and
/pci@80000000/usb@5,1/assigned-addresses; 8 is the offset of the
HcCommandStatus register; and the 1 bit is HostControllerReset (HCR).

Now I'm just trying to find the more correct way of doing it, without
hardcoded addresses. That'll be something like this:

  search the device tree for OHCI nodes
  for each OHCI node
    get assigned-addresses
    map-in
    set HCR
    wait for acknowledgement
    map-out

which can be done any time before the quiesce call, since that marks the
point where the kernel assumes that there are no devices writing to memory.
Sound good?

-- 
Alan Curry

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[Segher Boessenkool]

>> > Almost all of my devices are under that PCI node. What will I prove by
>> > disabling them?
>>
>> You should put it after "load", and before "go".
>>
>> It should give you a working system; it's a sledgehammer workaround.
>
> I can do it a little more gracefully than that. This works to deactivate
> the
> problem devices manually:
>
>   1 lbflip 80000000 8 + rl!
>   1 lbflip 80001000 8 + rl!
>
> where 80000000 and 80001000 have been obtained from
> /pci@80000000/usb@5/assigned-addresses and
> /pci@80000000/usb@5,1/assigned-addresses; 8 is the offset of the
> HcCommandStatus register; and the 1 bit is HostControllerReset (HCR).
>
> Now I'm just trying to find the more correct way of doing it, without
> hardcoded addresses. That'll be something like this:
>
>   search the device tree for OHCI nodes
>   for each OHCI node
>     get assigned-addresses
>     map-in
>     set HCR
>     wait for acknowledgement
>     map-out

As you noted, your firmware does not show which usb host controllers
are OHCI and which are not.  It has a lot of other problems as well.
Also, it's a lot of code to do things this way.  Which is why I suggested
the "heavy handed" workaround: it is simple and should work on even the
most broken OF implementations.

To figure out which host controllers are OHCI, you'll need to look
at the PCI class code (0c0310 for OHCI), since your OF doesn't want
to tell you.

> Sound good?

Sounds like it should work, yes.


Segher

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[pacman]

Segher Boessenkool writes:
> 
> > Now I'm just trying to find the more correct way of doing it, without
> > hardcoded addresses. That'll be something like this:
> >
> >   search the device tree for OHCI nodes
> >   for each OHCI node
> >     get assigned-addresses
> >     map-in
> >     set HCR
> >     wait for acknowledgement
> >     map-out
 
> Sounds like it should work, yes.
> 

I have a mostly-finished patch to do the above. I'll include it below, but
first a few words about why it's only mostly finished.

The other Pegasos workarounds are in fixup_device_tree_chrp, and I don't see
anything like an "if(machine_is_pegasos)" around them. What keeps them from
being erroneously run on other CHRP-type machines? I made this patch mainly
by copying pieces of other functions from prom_init.c, but couldn't find the
"test for Pegasos before running a Pegasos workaround" piece.

Another issue is, since the firmware doesn't give me a "compatible" property
with the details of the controller, I just have to assume that it's
little-endian. I'm not sure if that's clean, since the real ohci driver
supports both endiannesses, with at least 3 different Kconfig options(!) to
choose between them.

Then there's the volatile which I guess is supposed to be replaced by
something else, but I don't know what the something else is. I believe this
usage is extremely close to what volatile was meant for.

Finally, when I updated to a more recent upstream kernel to test the patch, I
found that an intervening commit (3df7169e73fc1d71a39cffeacc969f6840cdf52b,
OHCI: work around for nVidia shutdown problem) has had a major effect,
on the appearance of my bug.

Before that change, the window in which the bug could strike was from the end
of prom_init (when the kernel believes that devices are quiescent) to the
initialization of the ohci-hcd driver (which actually quietens the device, or
at least directs its scribbling to a properly allocated page). After the
change, the window ends at some point early in the PCI bus setup. That's a
window so small that with a new kernel, I can't provoke a symptom even if I
try.

Mostly-finished patch:

diff --git a/arch/powerpc/kernel/prom_init.c b/arch/powerpc/kernel/prom_init.c
index 941ff4d..a14f21b 100644
--- a/arch/powerpc/kernel/prom_init.c
+++ b/arch/powerpc/kernel/prom_init.c
@@ -2237,6 +2237,81 @@ static void __init fixup_device_tree_chrp(void)
 		}
 	}
 }
+
+/*
+ * Pegasos firmware doesn't quiesce OHCI controllers, so do it manually
+ */
+static void __init pegasos_quiesce(void)
+{
+	phandle node, parent_node;
+	ihandle parent_ih;
+	int rc;
+	char type[16], *path;
+	u32 prop[5], map_size;
+	prom_arg_t ohci_virt;
+
+	for (node = 0; prom_next_node(&node); ) {
+		memset(type, 0, sizeof(type));
+		prom_getprop(node, "device_type", type, sizeof(type));
+		if (strcmp(type, RELOC("usb")) != 0)
+			continue;
+
+		/* Parent should be a PCI bus (so class-code makes sense).
+		   class-code should be 0x0C0310 */
+		parent_node = call_prom("parent", 1, 1, node);
+		if (!parent_node)
+			continue;
+		rc = prom_getprop(node, "class-code", prop, sizeof(u32));
+		if (rc != sizeof(u32) || prop[0] != 0x0c0310)
+			continue;
+
+		rc = prom_getprop(node, "assigned-addresses",
+				  prop, 5*sizeof(u32));
+		if (rc != 5*sizeof(u32))
+			continue;
+
+		/* Open the parent and call map-in */
+
+		/* It seems OF doesn't null-terminate the path :-( */
+		path = RELOC(prom_scratch);
+		memset(path, 0, PROM_SCRATCH_SIZE);
+
+		if (call_prom("package-to-path", 3, 1, parent_node,
+			      path, PROM_SCRATCH_SIZE-1) == PROM_ERROR)
+			continue;
+		parent_ih = call_prom("open", 1, 1, path);
+
+		/* Get the OHCI node's pathname, for printing later */
+		memset(path, 0, PROM_SCRATCH_SIZE);
+		call_prom("package-to-path", 3, 1, node,
+			  path, PROM_SCRATCH_SIZE-1);
+
+		map_size = prop[4];
+		if (call_prom_ret("call-method", 6, 2, &ohci_virt,
+				  ADDR("map-in"), parent_ih,
+				  map_size, prop[0], prop[1], prop[2]) == 0) {
+			prom_printf("resetting OHCI device %s...", path);
+
+			/* Set HostControllerReset (==1) in HcCommandStatus,
+			 * located at offset 8 in the register area. The <<24
+			 * is because the CPU is big-endian and the device is
+			 * little-endian. */
+			*(volatile u32 *)(ohci_virt + 8) |= (1<<24);
+
+			/* controller should acknowledge by zeroing the bit
+			 * within 10us. waiting 1ms should be plenty. */
+			call_prom("interpret", 1, 1, "1 ms");
+			if (*(volatile u32 *)(ohci_virt + 8) & (1<<24))
+				prom_printf("failed\n");
+			else
+				prom_printf("done\n");
+
+			call_prom("call-method", 4, 1, ADDR("map-out"),
+				  parent_ih, map_size, ohci_virt);
+		}
+		call_prom("close", 1, 0, parent_ih);
+	}
+}
 #else
 #define fixup_device_tree_chrp()
 #endif
@@ -2642,6 +2717,7 @@ unsigned long __init prom_init(unsigned long r3, unsigned long r4,
 	 * devices etc...
 	 */
 	prom_printf("Calling quiesce...\n");
+	pegasos_quiesce();
 	call_prom("quiesce", 0, 0);
 
 	/*

-- 
Alan Curry

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug,

[Benjamin Herrenschmidt]

> I have a mostly-finished patch to do the above. I'll include it below, but
> first a few words about why it's only mostly finished.
> 
> The other Pegasos workarounds are in fixup_device_tree_chrp, and I don't see
> anything like an "if(machine_is_pegasos)" around them. What keeps them from
> being erroneously run on other CHRP-type machines? I made this patch mainly
> by copying pieces of other functions from prom_init.c, but couldn't find the
> "test for Pegasos before running a Pegasos workaround" piece.

Probably bcs the condition they test for really only happens on
pegasos ? :-)

I agree it's a bit gross tho.

The "ranges" property fixup is pretty harmless in any case. The other
fixup might be worth moving to a separate pegasos-only function in which
you would test for a pegasos properly and add your own stuff.

> Another issue is, since the firmware doesn't give me a "compatible" property
> with the details of the controller, I just have to assume that it's
> little-endian. I'm not sure if that's clean, since the real ohci driver
> supports both endiannesses, with at least 3 different Kconfig options(!) to
> choose between them.

If it's PCI it's LE or somebody needs to be shot :-)

> Then there's the volatile which I guess is supposed to be replaced by
> something else, but I don't know what the something else is. I believe this
> usage is extremely close to what volatile was meant for.

Yeah, it's fine, just add something like that on the next line:

 asm volatile("eieio" : : : "memory");

> Finally, when I updated to a more recent upstream kernel to test the patch, I
> found that an intervening commit (3df7169e73fc1d71a39cffeacc969f6840cdf52b,
> OHCI: work around for nVidia shutdown problem) has had a major effect,
> on the appearance of my bug.
> 
> Before that change, the window in which the bug could strike was from the end
> of prom_init (when the kernel believes that devices are quiescent) to the
> initialization of the ohci-hcd driver (which actually quietens the device, or
> at least directs its scribbling to a properly allocated page). After the
> change, the window ends at some point early in the PCI bus setup. That's a
> window so small that with a new kernel, I can't provoke a symptom even if I
> try.

Right but it's very fishy, ie, it may still be DMA'ing and god knows
where ... you may or may not get lucky. I'd rather you do a proper
fixup :-)

Cheers,
Ben.

> Mostly-finished patch:
> 
> diff --git a/arch/powerpc/kernel/prom_init.c b/arch/powerpc/kernel/prom_init.c
> index 941ff4d..a14f21b 100644
> --- a/arch/powerpc/kernel/prom_init.c
> +++ b/arch/powerpc/kernel/prom_init.c
> @@ -2237,6 +2237,81 @@ static void __init fixup_device_tree_chrp(void)
>  		}
>  	}
>  }
> +
> +/*
> + * Pegasos firmware doesn't quiesce OHCI controllers, so do it manually
> + */
> +static void __init pegasos_quiesce(void)
> +{
> +	phandle node, parent_node;
> +	ihandle parent_ih;
> +	int rc;
> +	char type[16], *path;
> +	u32 prop[5], map_size;
> +	prom_arg_t ohci_virt;
> +
> +	for (node = 0; prom_next_node(&node); ) {
> +		memset(type, 0, sizeof(type));
> +		prom_getprop(node, "device_type", type, sizeof(type));
> +		if (strcmp(type, RELOC("usb")) != 0)
> +			continue;
> +
> +		/* Parent should be a PCI bus (so class-code makes sense).
> +		   class-code should be 0x0C0310 */
> +		parent_node = call_prom("parent", 1, 1, node);
> +		if (!parent_node)
> +			continue;
> +		rc = prom_getprop(node, "class-code", prop, sizeof(u32));
> +		if (rc != sizeof(u32) || prop[0] != 0x0c0310)
> +			continue;
> +
> +		rc = prom_getprop(node, "assigned-addresses",
> +				  prop, 5*sizeof(u32));
> +		if (rc != 5*sizeof(u32))
> +			continue;
> +
> +		/* Open the parent and call map-in */
> +
> +		/* It seems OF doesn't null-terminate the path :-( */
> +		path = RELOC(prom_scratch);
> +		memset(path, 0, PROM_SCRATCH_SIZE);
> +
> +		if (call_prom("package-to-path", 3, 1, parent_node,
> +			      path, PROM_SCRATCH_SIZE-1) == PROM_ERROR)
> +			continue;
> +		parent_ih = call_prom("open", 1, 1, path);
> +
> +		/* Get the OHCI node's pathname, for printing later */
> +		memset(path, 0, PROM_SCRATCH_SIZE);
> +		call_prom("package-to-path", 3, 1, node,
> +			  path, PROM_SCRATCH_SIZE-1);
> +
> +		map_size = prop[4];
> +		if (call_prom_ret("call-method", 6, 2, &ohci_virt,
> +				  ADDR("map-in"), parent_ih,
> +				  map_size, prop[0], prop[1], prop[2]) == 0) {
> +			prom_printf("resetting OHCI device %s...", path);
> +
> +			/* Set HostControllerReset (==1) in HcCommandStatus,
> +			 * located at offset 8 in the register area. The <<24
> +			 * is because the CPU is big-endian and the device is
> +			 * little-endian. */
> +			*(volatile u32 *)(ohci_virt + 8) |= (1<<24);
> +
> +			/* controller should acknowledge by zeroing the bit
> +			 * within 10us. waiting 1ms should be plenty. */
> +			call_prom("interpret", 1, 1, "1 ms");
> +			if (*(volatile u32 *)(ohci_virt + 8) & (1<<24))
> +				prom_printf("failed\n");
> +			else
> +				prom_printf("done\n");
> +
> +			call_prom("call-method", 4, 1, ADDR("map-out"),
> +				  parent_ih, map_size, ohci_virt);
> +		}
> +		call_prom("close", 1, 0, parent_ih);
> +	}
> +}
>  #else
>  #define fixup_device_tree_chrp()
>  #endif
> @@ -2642,6 +2717,7 @@ unsigned long __init prom_init(unsigned long r3, unsigned long r4,
>  	 * devices etc...
>  	 */
>  	prom_printf("Calling quiesce...\n");
> +	pegasos_quiesce();
>  	call_prom("quiesce", 0, 0);
>  
>  	/*
> 

Re: Pegasos OHCI bug (was Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55)

[Benjamin Herrenschmidt]

> Since then, the silence has been deafening.
> 
> My assumption now is that this is not ever getting fixed. I'm certainly not
> able to fix it. I'm not a even kernel programmer! I got far enough to
> diagnose the cause just with the "add more printk's and boot it again"
> technique. Hundreds of reboots trying to figure it out. I was a conscientious
> bug-reporter, I thought.

I'm happy to help you fix it but I'm travelling at the moment and won't
have much time for a couple of weeks.

Cheers,
Ben.

> I could pull the PCI card and be done with it. I never used those USB ports
> anyway. But after all the suffering I went through to find this bug... the
> crashing e2fsck's and consequent filesystem corruption... I hate the idea of
> surrendering to it. There are possibly other affected users who I'd be
> abandoning to suffer similarly in the future.
> 
> For the last week I've studied OpenFirmware as hard as I can. I read the spec
> cover to cover. And the USB annex, and the PCI annex. But I'm still lost in
> all the different address formats.
> 
> I took my best guess on how to handle this problem, and ran with it, ending
> up with a 97-line Forth script, and that was just to get a virtual address,
> not to actually do anything with it, and it used a hardcoded device path. But
> it didn't work, all I got was an "invalid pointer" error. I made another
> guess at something that wasn't documented anywhere (the fact that this stuff
> is insufficiently documented is the one thing I can state with complete
> confidence!) and out came a successful translation to a virtual address: 0.
> 
> If I'm the only one fighting this bug, the bug wins.
> 

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Tue, 2010-10-19 at 13:10 -0500, pacman@kosh.dhis.org wrote:
> 
> So what type of driver, firmware, or hardware bug puts a 16-bit 1000Hz
> timer
> in memory, and does it in little-endian instead of the CPU's native
> byte
> order? And why does it stop doing it some time during the early init
> scripts,
> shortly after the root filesystem fsck?
> 
> I have not yet attempted to repeat the experiment. If it is
> repeatable, I'll
> probe more deeply into those init scripts later. I'm looking hard at
> /etc/rcS.d/S11hwclock.sh 

Stinks of USB...

Ben.

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Andrew Morton]

On Mon, 18 Oct 2010 12:33:31 +0100
Mel Gorman <mel@csn.ul.ie> wrote:

> A bit but I still don't know why it would cause corruption. Maybe this is still
> a caching issue but the difference in timing between list_add and list_add_tail
> is enough to hide the bug. It's also possible there are some registers
> ioremapped after the memmap array and reading them is causing some
> problem.
> 
> Andrew, what is the right thing to do here? We could flail around looking
> for explanations as to why the bug causes a user buffer corruption but never
> get an answer or do we go with this patch, preferably before 2.6.36 releases?

Well, you've spotted a bug so I'd say we fix it asap.

It's a bit of a shame that we lose the only known way of reproducing a
different bug, but presumably that will come back and bite someone else
one day, and we'll fix it then :(

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Mon, 2010-10-18 at 12:37 -0700, Andrew Morton wrote:
> Well, you've spotted a bug so I'd say we fix it asap.
> 
> It's a bit of a shame that we lose the only known way of reproducing a
> different bug, but presumably that will come back and bite someone
> else
> one day, and we'll fix it then :(

Well, I can always revert that and run some experiments here, provided I
can reproduce the problem at all ...

Cheers,
Ben.

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Thomas Gleixner]

On Mon, 18 Oct 2010, Andrew Morton wrote:

> On Mon, 18 Oct 2010 12:33:31 +0100
> Mel Gorman <mel@csn.ul.ie> wrote:
> 
> > A bit but I still don't know why it would cause corruption. Maybe this is still
> > a caching issue but the difference in timing between list_add and list_add_tail
> > is enough to hide the bug. It's also possible there are some registers
> > ioremapped after the memmap array and reading them is causing some
> > problem.
> > 
> > Andrew, what is the right thing to do here? We could flail around looking
> > for explanations as to why the bug causes a user buffer corruption but never
> > get an answer or do we go with this patch, preferably before 2.6.36 releases?
> 
> Well, you've spotted a bug so I'd say we fix it asap.
> 
> It's a bit of a shame that we lose the only known way of reproducing a
> different bug, but presumably that will come back and bite someone else
> one day, and we'll fix it then :(

I might be completely one off as usual, but this thing reminds me of a
bug I stared at yesterday night:

    http://permalink.gmane.org/gmane.linux.kernel/1049605

Reporter Cc'ed

Thanks,

	tglx

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Helmut Grohne]

On Mon, Oct 18, 2010 at 11:55:44PM +0200, Thomas Gleixner wrote:
> I might be completely one off as usual, but this thing reminds me of a
> bug I stared at yesterday night:

This problem is completely unrelated. My problem was caused by using
binutils-gold.

Helmut

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Thomas Gleixner]

On Tue, 19 Oct 2010, Helmut Grohne wrote:

> On Mon, Oct 18, 2010 at 11:55:44PM +0200, Thomas Gleixner wrote:
> > I might be completely one off as usual, but this thing reminds me of a
> > bug I stared at yesterday night:
> 
> This problem is completely unrelated. My problem was caused by using
> binutils-gold.

Ok, thanks for the update. One thing less to worry about :)

Thanks,

	tglx

Re: PROBLEM: memory corrupting bug, bisected to 6dda9d55

[Benjamin Herrenschmidt]

On Wed, 2010-10-13 at 15:40 +0100, Mel Gorman wrote:
> 
> This is somewhat contrived but I can see how it might happen even on one
> CPU particularly if the L1 cache is virtual and is loose about checking
> physical tags.
> 
> > How sensitive/vulnerable is PPC32 to such things?
> > 
> 
> I can not tell you specifically but if the above scenario is in any way
> plausible, I believe it would depend on what sort of L1 cache the CPU
> has. Maybe this particular version has a virtual cache with no physical
> tagging and is depending on the OS not to make virtual aliasing mistakes.

Nah, ppc doesn't have problems with cache aliases, it all looks
physically tagged to the programmer (tho there's subtleties but none
that explains the reported behaviour).

Looks like real memory corruption to me.

Cheers,
Ben.