On 09/01/2010 08:10 AM, Darren Hart wrote:

On 08/31/2010 10:54 PM, Michael Ellerman wrote:

quoted

On Tue, 2010-08-31 at 00:12 -0700, Darren Hart wrote:
..

quoted

When running with the function plugin I had to stop the trace
immediately before entering start_secondary after an online or my traces
would not include the pseries_mach_cpu_die function, nor the tracing I
added there (possibly buffer size, I am using 2048). The following trace
was collected using "trace-cmd record -p function -e irq -e sched" and
has been filtered to only show CPU [001] (the CPU undergoing the
offline/online test, and the one seeing preempt_count (pcnt) go to
ffffffff after cede. The function tracer does not indicate anything
running on the CPU other than the HCALL - unless the __trace_hcall*
commands might be to blame. 

It's not impossible. Though normally they're disabled right, so the only
reason they're running is because you're tracing. So if they are causing
the bug then that doesn't explain why you see it normally.

Still, might be worth disabling just the hcall tracepoints just to be
100% sure.

A couple of updates. I was working from tip/rt/head, which has been
stale for some months now. I switched to tip/rt/2.6.33 and the
preempt_count() change over cede went away. I now see the live hang that
Will has reported.

Before I dive into the live hang, I want to understand what fixed the
preempt_count() change. That might start pointing us in the right
direction for the live hang.

I did an inverted git bisect between tip/rt/head and tip/rt/2.6.33 to
try and locate the fix. I've narrowed it down to the 2.6.33.6 merge:

# git show 7e1af1172bbd4109d09ac515c5d376f633da7cff
commit 7e1af1172bbd4109d09ac515c5d376f633da7cff
Merge: d8e94db 9666790
Author: Thomas Gleixner [off-list ref]
Date:   Tue Jul 13 16:01:16 2010 +0200

    Merge
git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-2.6.33.y

    Conflicts:
        Makefile

    Signed-off-by: Thomas Gleixner [off-list ref]


Visual inspection yields two patches of interest:

f8b67691828321f5c85bb853283aa101ae673130
powerpc/pseries: Make query-cpu-stopped callable outside hotplug cpu

aef40e87d866355ffd279ab21021de733242d0d5
powerpc/pseries: Only call start-cpu when a CPU is stopped

I'm going to try reverting these today and see if they addressed the
issue indirectly.

Removing:

aef40e87d866355ffd279ab21021de733242d0d5
powerpc/pseries: Only call start-cpu when a CPU is stopped

--- a/arch/powerpc/platforms/pseries/smp.c
+++ b/arch/powerpc/platforms/pseries/smp.c

@@ -82,6 +82,12 @@ static inline int __devinit smp_startup_cpu(unsigned int lcpu)
 
        pcpu = get_hard_smp_processor_id(lcpu);
 
+       /* Check to see if the CPU out of FW already for kexec */

This comment is really confusing to me. I _think_ it is saying that this test
determines if the CPU is done executing firmware code and has begun executing
OS code.... Is that right?

+       if (smp_query_cpu_stopped(pcpu) == QCSS_NOT_STOPPED){
+               cpu_set(lcpu, of_spin_map);
+               return 1;
+       }
+
        /* Fixup atomic count: it exited inside IRQ handler. */
        task_thread_info(paca[lcpu].__current)->preempt_count   = 0;

from tip/rt/2.6.33 causes the preempt_count() to change across the cede
call.  This patch appears to prevents the proxy preempt_count assignment
from happening. This non-local-cpu assignment to 0 would cause an
underrun of preempt_count() if the local-cpu had disabled preemption
prior to the assignment and then later tried to enable it. This appears
to be the case with the stack of __trace_hcall* calls preceeding the
return from extended_cede_processor() in the latency format trace-cmd
report:

  <idle>-0       1d....   201.252737: function:             .cpu_die
  <idle>-0       1d....   201.252738: function:                .pseries_mach_cpu_die
  <idle>-0       1d....   201.252740: function:                   .idle_task_exit
  <idle>-0       1d....   201.252741: function:                      .switch_slb
  <idle>-0       1d....   201.252742: function:                   .xics_teardown_cpu
  <idle>-0       1d....   201.252743: function:                      .xics_set_cpu_priority
  <idle>-0       1d....   201.252744: function:             .__trace_hcall_entry
  <idle>-0       1d..1.   201.252745: function:                .probe_hcall_entry
  <idle>-0       1d..1.   201.252746: function:             .__trace_hcall_exit
  <idle>-0       1d..2.   201.252747: function:                .probe_hcall_exit
  <idle>-0       1d....   201.252748: function:             .__trace_hcall_entry
  <idle>-0       1d..1.   201.252748: function:                .probe_hcall_entry
  <idle>-0       1d..1.   201.252750: function:             .__trace_hcall_exit
  <idle>-0       1d..2.   201.252751: function:                .probe_hcall_exit
  <idle>-0       1d....   201.252752: function:             .__trace_hcall_entry
  <idle>-0       1d..1.   201.252753: function:                .probe_hcall_entry
  offon.sh-3684  6.....   201.466488: bprint:               .smp_pSeries_kick_cpu : resetting pcnt to 0 for cpu 1

preempt_count() is reset from 1 to 0 by smp_startup_cpu() without the
QCSS_NOT_STOPPED check from the patch above.

  <idle>-0       1d....   201.466503: function:             .__trace_hcall_exit
  <idle>-0       1d..1.   201.466505: function:                .probe_hcall_exit
  <idle>-0       1d.Hff.   201.466507: bprint:               .pseries_mach_cpu_die : after cede: ffffffff

With the preempt_count() being one less than it should be, the final
preempt_enable() in the trace_hcall path drops preempt_count to
0xffffffff, which of course is an illegal value and leads to a crash.

I don't know if the patch above is the "right fix" for this or not as
don't yet understand why this occurs only with PREEMPT_RT and not in
mainline. Once we sort that out, we may need a more specific fix.

Many thanks to Steven Rostedt for pouring over the trace and the trace
code with me.

Thanks,

-- 
Darren Hart
IBM Linux Technology Center
Real-Time Linux Team