Messages in this thread | | | Date | Thu, 23 Apr 2009 10:39:46 -0400 (EDT) | From | Steven Rostedt <> | Subject | Re: [PATCH 0/2] [GIT PULL] tracing: various bug fixes |
| |
On Thu, 23 Apr 2009, Steven Rostedt wrote:
> > On Thu, 23 Apr 2009, Ingo Molnar wrote: > > > > > > > Here's the situation: > > > > > > We've added selftests for the event tracer. What this basically does is > > > enables each event one at a time and runs tests. The tests include > > > creating a kernel thread, executing workqueues and grabbing locks. > > > > > > We also have PROVE_LOCKING (LOCKDEP) enabled, that keeps track of > > > interrupts being enabled. When they are, we set a flag in the task struct > > > "hardirqs_enabled". When they are disabled, this flag is cleared. > > > > > > When we fork a process, a test is made to see if the flag is set for the > > > new process and if it is not, a warning is printed (as is done in the > > > above dump). > > > > > > I investigated this and found that the flag is mysteriously being set and > > > cleared for no apparent reason. The flag is in the task struct and nothing > > > should be touching it. In fact, it is a full int, not even a bit in a > > > flags variable. > > > > > > I had a test that would print the flag and irqs_disabled() in copy_process > > > before the warning and it showed that the flag was cleared but irqs was > > > enabled. The funny part is, I if the test triggered, I printed the flag > > > again, and the second print it was set again!! > > > > > > if (!p->hardirqs_enabled) { > > > printk("irqs:%d flag:%d\n", irqs_disabled(), > > > p->hardirqs_enabled); > > > printk("try again: %d\n", p->hardirqs_enabled); > > > } > > > > > > The first print showed that it was cleared, the second showed it was set > > > again?? > > > > function tracer was active? So somewhere there we corrupted this > > state? It's unlikely that printk itself did this. > > The problem always arises at the same spot. I'm not saying printk was the > culprit, I'm saying that printk actually "fixed" the issue. Which can be a > sign of a corrupted register somewhere. > > I currently tracked it down to something in "prep_new_page". It is hard to > debug because as I add tests into the code, it makes the race window > smaller, and I need to run multiple boots to trigger the code. But when I > do trigger it (and I try to trigger it a few times) it always happens at > the same spot. > > Note, everytime I catch the issue, the printk again "fixes" the problem > :-/ > > Since I need both DEBUG_PAGEALLOC and PARAVIRT on, I'm thinking that the > debug page alloc might be messing with the paravirt "modified" code (or > vice versa). It could also be the function tracer doing it too. But it > looks like the DEBUG_PAGEALLOC code is causing issues because the bug > always appears in the alloc code. > > I'm not blaming any subsystem yet. It just seems that the combination of > these systems are broken.
OK, now I need help :-p
I traced the corruption down to the __flush_tlb_all() in kernel_map_pages. This is only called when DEBUG_PAGEALLOC is enabled, thus this explains why DEBUG_PAGEALLOC must be set.
Now it may be an issue between the function tracer and paravirt.
The __flush_tlb_all is:
static inline void __flush_tlb_all(void) { if (cpu_has_pge) __flush_tlb_global(); else __flush_tlb(); }
Which, on my box calls __flush_tlb_global()
which is a paravirt call:
static void native_flush_tlb_global(void) { __native_flush_tlb_global(); }
Even though the alternative code makes this a direct call, it is still traced by ftrace. Heck, even the calls in __native_flush_tlb_global call into paravirt (read_cr4 and write_cr4).
static inline void __native_flush_tlb_global(void) { unsigned long flags; unsigned long cr4;
/* * Read-modify-write to CR4 - protect it from preemption and * from interrupts. (Use the raw variant because this code can * be called from deep inside debugging code.) */ raw_local_irq_save(flags);
cr4 = read_cr4(); /* clear PGE */ write_cr4(cr4 & ~X86_CR4_PGE); /* write old PGE again and flush TLBs */ write_cr4(cr4);
raw_local_irq_restore(flags); }
Each of those read_cr4 and write_cr4 can be traced. But I still do not see how this can cause corruption in the current task struct.
The TLB just caches the pages we are using, not the contents inside. I still do not see how this can corrupt a bit. Unless a register leaked :-/
-- Steve
| |