Re: 2.6.31-rc5 regression: x86 MCE malfunction on Thinkpad T42p

[Ingo Molnar <mingo@elte.hu>]

* Johannes Stezenbach <js@sig21.net> wrote:

> On Mon, Aug 10, 2009 at 03:29:23PM +0200, Ingo Molnar wrote:
> > * Johannes Stezenbach <js@sig21.net> wrote:
> > > On Mon, Aug 10, 2009 at 02:32:28PM +0200, Andi Kleen wrote:
> > > > 
> > > > When the BIOS doesn't enable it then force enabling lapic might not work.
> > > > 
> > > > This could cause either boot failures (obvious) or more subtle 
> > > > problems like SMM doing something unexpected. Just saying that 
> > > > if you have strange problems later first try disabling this 
> > > > option again.
> > > 
> > > Thanks for the heads-up.  I remember I tried to use oprofile in 
> > > the past on this machine and was disappointed that it only got the 
> > > timer event.  I'll keep lapic for now unless I see signs of 
> > > instability.
> > 
> > What's the output of something like 'perf stat true', and does 'perf 
> > top' output something - i.e. do perfcounters work in general? Once 
> > you get to that stage and it works then it should be fine.
> 
> # ./perf stat true
> 
>  Performance counter stats for 'true':
> 
>        0.985808  task-clock-msecs         #      0.779 CPUs 
>               0  context-switches         #      0.000 M/sec
>               0  CPU-migrations           #      0.000 M/sec
>             110  page-faults              #      0.112 M/sec
>          583873  cycles                   #    592.279 M/sec
>          500937  instructions             #      0.858 IPC  
>   <not counted>  cache-references        
>   <not counted>  cache-misses            
> 
>     0.001265524  seconds time elapsed

That looks almost normal - except for cache-references and 
cache-misses that is not counted. Could you send the /proc/cpuinfo 
info please?

> 
> 
> # ./perf top
> ------------------------------------------------------------------------------
>    PerfTop:     172 irqs/sec  kernel:43.6% [100000 cycles],  (all, 1 CPUs)
> ------------------------------------------------------------------------------
> 
>              samples    pcnt         RIP          kernel function
>   ______     _______   _____   ________________   _______________
> 
>                96.00 - 16.4% - 00000000c129be10 : acpi_pm_read
>                66.00 - 11.3% - 00000000c116fbb1 : delay_tsc
>                59.00 - 10.1% - 00000000c1172a83 : ioread32
>                26.00 -  4.4% - 00000000c116f567 : vsnprintf
>                21.00 -  3.6% - 00000000c11a4721 : acpi_os_read_port
>                20.00 -  3.4% - 00000000c136612c : schedule
>                19.00 -  3.2% - 00000000c10054b9 : mask_and_ack_8259A
>                18.00 -  3.1% - 00000000c11ce8bc : acpi_idle_enter_bm
>                17.00 -  2.9% - 00000000c1090dd1 : do_select
>                16.00 -  2.7% - 00000000c133f380 : unix_poll
>                14.00 -  2.4% - 00000000c116e2b4 : number
>                13.00 -  2.2% - 00000000c1002847 : sysenter_past_esp
>                10.00 -  1.7% - 00000000c1085b84 : fget_light
>                 9.00 -  1.5% - 00000000c13666a7 : preempt_schedule
>                 9.00 -  1.5% - 00000000c102cf1b : get_next_timer_interrupt
> ^C

Ok, this looks normal.

> First I tried oprofile while running an endless while loop in bash:
> 
> # opreport 
> CPU: Pentium M (P6 core), speed 1800 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (clocks processor is not halted, and not in a thermal trip) with a unit mask of 0x00 (No unit mask) count 100000
> CPU_CLK_UNHALT...|
>   samples|      %|
> ------------------
>    282940 76.5545 bash
>     78266 21.1763 libc-2.9.so
>      1730  0.4681 Xorg
>      1069  0.2892 oprofiled
> 
> Looks plausible.

Yeah.

> But in demsg I got this:
> 
> Delta way too big! 18446744022868427516 ts=18446744022868427516 write stamp = 0
> ------------[ cut here ]------------
> WARNING: at kernel/trace/ring_buffer.c:1392 rb_reserve_next_event+0x150/0x309()
> Hardware name: 2373Y4M
> Modules linked in: ath5k mac80211 ath cfg80211 oprofile bnep sco rfcomm l2cap bluetooth ehci_hcd uhci_hc
> Pid: 13478, comm: opcontrol Not tainted 2.6.31-rc5 #5
> Call Trace:
>  [<c10248dd>] warn_slowpath_common+0x60/0x90
>  [<c102491a>] warn_slowpath_null+0xd/0x10
>  [<c1054129>] rb_reserve_next_event+0x150/0x309
>  [<c1068c06>] ? get_page_from_freelist+0x86/0x35a
>  [<c10544f7>] ring_buffer_lock_reserve+0xe7/0x135
>  [<f88622c0>] op_cpu_buffer_write_reserve+0x1a/0x4b [oprofile]
>  [<f886239d>] op_add_code+0x57/0x98 [oprofile]
>  [<c1068c06>] ? get_page_from_freelist+0x86/0x35a
>  [<c1367c08>] ? page_fault+0x0/0x8
>  [<f8862409>] log_sample+0x2b/0x6c [oprofile]
>  [<c1064c76>] ? filemap_fault+0x74/0x32b
>  [<f886249c>] oprofile_add_sample+0x3b/0x6b [oprofile]
>  [<f88641d8>] ppro_check_ctrs+0x66/0xdb [oprofile]
>  [<c1074bde>] ? __do_fault+0x303/0x32f
>  [<f8863907>] profile_exceptions_notify+0x1f/0x26 [oprofile]
>  [<c103953b>] notifier_call_chain+0x2b/0x55
>  [<c10398e3>] __atomic_notifier_call_chain+0x1a/0x3a
>  [<c103990f>] atomic_notifier_call_chain+0xc/0xe
>  [<c103993e>] notify_die+0x2d/0x2f
>  [<c1003c54>] do_nmi+0x63/0x222
>  [<c1367d1d>] nmi_stack_correct+0x28/0x2d
>  [<c1367c08>] ? page_fault+0x0/0x8
> ---[ end trace d174f39c63495e01 ]---

That's a new warning i havent seen before - i've Cc:-ed Robert 
(oprofile maintainer) and Steve (ftrace/ring-buffer maintainer) for 
that.

The warning is probably harmless - oprofile sampling still works 
fine, right?

	Ingo