2.6.31-rc5 regression: x86 MCE malfunction on Thinkpad T42p
Hi,
I'm currently running linux-2.6.31-rc5-246-g90bc1a6 on an old Thinkpad T42p. During boot I get the following:
Local APIC disabled by BIOS -- you can enable it with "lapic"
APIC: disable apic facility
...
mce: CPU supports 5 MCE banks
Disabling lock debugging due to kernel taint
------------[ cut here ]------------
WARNING: at arch/x86/kernel/apic/apic.c:247 native_apic_write_dummy+0x2d/0x39()
Hardware name: 2373Y4M
Modules linked in:
Pid: 0, comm: swapper Tainted: G M 2.6.31-rc5 #1
Call Trace:
[<c10248c1>] warn_slowpath_common+0x60/0x90
[<c10248fe>] warn_slowpath_null+0xd/0x10
[<c1013139>] native_apic_write_dummy+0x2d/0x39
[<c100dcd2>] intel_init_thermal+0xb6/0x144
[<c100d517>] ? mce_init+0x33/0xb0
[<c100db4b>] mce_intel_feature_init+0xb/0x4c
[<c14fc31e>] mcheck_init+0x1e2/0x253
[<c14faef4>] identify_cpu+0x30b/0x31b
[<c14d9af0>] identify_boot_cpu+0xd/0x23
[<c14d9b3c>] check_bugs+0xb/0xd4
[<c104f929>] ? delayacct_init+0x42/0x49
[<c14d493c>] start_kernel+0x25e/0x26d
[<c14d430b>] i386_start_kernel+0x65/0x6a
---[ end trace 4eaa2a86a8e2da22 ]---
...
CPU: Intel(R) Pentium(R) M processor 1.80GHz stepping 06mcelog reports:
HARDWARE ERROR. This is *NOT* a software problem! Please contact your hardware vendor
MCE 0
CPU 0 BANK 1
TIME 1249662514 Fri Aug 7 18:28:34 2009 MCG status:
MCi status:
Error overflow
Uncorrected error
Error enabled
Processor context corrupt
MCA: Unknown Error 30
STATUS f200000000000030 MCGSTATUS 0 MCGCAP 5 APICID 0 SOCKETID 0
CPUID Vendor Intel Family 6 Model 13
In .config I have:
CONFIG_X86_UP_APIC=y
# CONFIG_X86_UP_IOAPIC is not set CONFIG_X86_LOCAL_APIC=y CONFIG_X86_IO_APIC=y
# CONFIG_X86_REROUTE_FOR_BROKEN_BOOT_IRQS is not set CONFIG_X86_MCE=y
# CONFIG_X86_OLD_MCE is not set CONFIG_X86_NEW_MCE=y
CONFIG_X86_MCE_INTEL=y
# CONFIG_X86_MCE_AMD is not set
# CONFIG_X86_ANCIENT_MCE is not set CONFIG_X86_MCE_THRESHOLD=y
# CONFIG_X86_MCE_INJECT is not set CONFIG_X86_THERMAL_VECTOR=y
I guess I should try to boot with "lapic"? But I think MCE worked without "lapic" in earlier kernels. On a 2.6.29.1 kernel dmesg said:
Local APIC disabled by BIOS -- you can enable it with "lapic"
...
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
2.6.29.1 doesn't log any MCE events, so I doubt this is a HW problem.
Johannes
Quoted 3 lines · Johannes Stezenbach
I'm currently running linux-2.6.31-rc5-246-g90bc1a6 on an old Thinkpad T42p. During boot I get the following:
...
Quoted 10 lines
I guess I should try to boot with "lapic"? But I think MCE worked without "lapic" in earlier kernels. On a 2.6.29.1 kernel dmesg said:
Local APIC disabled by BIOS -- you can enable it with "lapic"
...
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.2.6.29.1 doesn't log any MCE events, so I doubt this is a HW problem.
I booted with "lapic", then the backtrace is gone but it still logs machine check events which I think are bogus since 2.6.29.1 does not log any. I also tried 2.6.30, no machine check messages in dmesg. But I noticed that mcelog complains about missing /dev/mcelog, it seems that /dev/mcelog support for 32bit kernels is new. However, I guess the old kernels should still have printed a messge to dmesg, right? "Uncorrected error" + "Processor context corrupt" sounds pretty serious, but the machine runs without problems.
These are from 2.6.31-rc5 by running mcelog (dmesg just says "Machine check events logged"):
HARDWARE ERROR. This is *NOT* a software problem!
Please contact your hardware vendor
MCE 0
CPU 0 BANK 1
TIME 1249725930 Sat Aug 8 12:05:30 2009
MCG status:
MCi status:
Error overflow
Uncorrected error
Error enabled
Processor context corrupt
MCA: MEMORY CONTROLLER AC_CHANNEL0_ERR
Transaction: Address/Command error
STATUS f2000000000000b0 MCGSTATUS 0
MCGCAP 5 APICID 0 SOCKETID 0
CPUID Vendor Intel Family 6 Model 13
HARDWARE ERROR. This is *NOT* a software problem!
Please contact your hardware vendor
MCE 1
CPU 0 BANK 1
TIME 1249728066 Sat Aug 8 12:41:06 2009
MCG status:
MCi status:
Error overflow
Uncorrected error
Error enabled
Processor context corrupt
MCA: Unknown Error 20
STATUS f200000000000020 MCGSTATUS 0
MCGCAP 5 APICID 0 SOCKETID 0
CPUID Vendor Intel Family 6 Model 13
HARDWARE ERROR. This is *NOT* a software problem!
Please contact your hardware vendor
MCE 2
CPU 0 BANK 1
TIME 1249747923 Sat Aug 8 18:12:03 2009
MCG status:
MCi status:
Error overflow
Uncorrected error
Error enabled
Processor context corrupt
MCA: Unknown Error 30
STATUS f200000000000030 MCGSTATUS 0
MCGCAP 5 APICID 0 SOCKETID 0
CPUID Vendor Intel Family 6 Model 13
HARDWARE ERROR. This is *NOT* a software problem!
Please contact your hardware vendor
MCE 3
CPU 0 BANK 1
TIME 1249765938 Sat Aug 8 23:12:18 2009
MCG status:
MCi status:
Error overflow
Uncorrected error
Error enabled
Processor context corrupt
MCA: Unknown Error 20
STATUS f200000000000020 MCGSTATUS 0
MCGCAP 5 APICID 0 SOCKETID 0
CPUID Vendor Intel Family 6 Model 13
Johannes
Quoted 9 lines · On Sunday 09 August 2009 12:03:48 Johannes Stezenbach wrote:
Quoted 3 lines · Johannes Stezenbach
I'm currently running linux-2.6.31-rc5-246-g90bc1a6 on an old Thinkpad T42p. During boot I get the following:
...
Quoted 4 lines
I guess I should try to boot with "lapic"? But I think MCE worked without "lapic" in earlier kernels. On a 2.6.29.1 kernel dmesg said:
Quoted 6 lines
Quoted 6 lines
Local APIC disabled by BIOS -- you can enable it with "lapic"
...
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.2.6.29.1 doesn't log any MCE events, so I doubt this is a HW problem.
Quoted 10 lines · Bartlomiej Zolnierkiewicz
Quoted 7 lines · On Sunday 09 August 2009 12:03:48 Johannes Stezenbach wrote:
Quoted 3 lines · Johannes Stezenbach
I'm currently running linux-2.6.31-rc5-246-g90bc1a6 on an old Thinkpad T42p. During boot I get the following:
...
Quoted 2 lines
2.6.29.1 doesn't log any MCE events, so I doubt this is a HW problem.
This patch fixes the issue for me.
Thanks,
Johannes
Quoted 4 lines · Johannes Stezenbach
Hi,
I'm currently running linux-2.6.31-rc5-246-g90bc1a6 on an old Thinkpad T42p. During boot I get the following:
Thanks for the report.
Quoted 11 lines
Local APIC disabled by BIOS -- you can enable it with "lapic"
APIC: disable apic facility
...
mce: CPU supports 5 MCE banks
Disabling lock debugging due to kernel taint------------[ cut here ]------------ WARNING: at arch/x86/kernel/apic/apic.c:247 native_apic_write_dummy+0x2d/0x39() Hardware name: 2373Y4M Modules linked in: Pid: 0, comm: swapper Tainted: G M 2.6.31-rc5 #1
The mcelog below is already worked around with Bart's patch he posted the link to (it's really a BIOS bug in your case that the BIOS leaves junks in the machine check registers on boot)
[for the x86 maintainers:]
One thing that would be good to make sure that Bart's patch is queued for .31 too, not only for .32, since this BIOS problem seems to be common (already two reports)
But still need to fix that warning too, which is independent [another .31 candidate]
Quoted 7 lines
Call Trace:
[<c10248c1>] warn_slowpath_common+0x60/0x90
[<c10248fe>] warn_slowpath_null+0xd/0x10
[<c1013139>] native_apic_write_dummy+0x2d/0x39
[<c100dcd2>] intel_init_thermal+0xb6/0x144
[<c100d517>] ? mce_init+0x33/0xb0
[<c100db4b>] mce_intel_feature_init+0xb/0x4cQuoted 8 lines
[<c14fc31e>] mcheck_init+0x1e2/0x253
[<c14faef4>] identify_cpu+0x30b/0x31b
[<c14d9af0>] identify_boot_cpu+0xd/0x23
[<c14d9b3c>] check_bugs+0xb/0xd4
[<c104f929>] ? delayacct_init+0x42/0x49
[<c14d493c>] start_kernel+0x25e/0x26d
[<c14d430b>] i386_start_kernel+0x65/0x6a
---[ end trace 4eaa2a86a8e2da22 ]---The appended patch should remove the warning. Can you please test it?
Quoted 1 line
2.6.29.1 doesn't log any MCE events, so I doubt this is a HW problem.
It actually is a BIOS bug, but not really broken hardware.
-Andi
---
Don't try to enable thermal throttling on 32bit systems without apic
When the local APIC isn't enabled don't try to enable thermal throttling. The APIC writes would WARN_ON.
Fixes
Quoted 6 lines
Disabling lock debugging due to kernel taint
------------[ cut here ]------------ WARNING: at arch/x86/kernel/apic/apic.c:247 native_apic_write_dummy+0x2d/0x39() Hardware name: 2373Y4M Modules linked in: Pid: 0, comm: swapper Tainted: G M 2.6.31-rc5 #1
Originally reported by Johannes Stezenbach
This is a 2.6.31 candidate because it fixes a regression.
--- arch/x86/kernel/cpu/mcheck/therm_throt.c | 3 +++ 1 file changed, 3 insertions(+)
arch/x86/kernel/cpu/mcheck/therm_throt.c +3 -0
@@ -236,6 +236,9 @@ void intel_init_thermal(struct cpuinfo_xint tm2 =0 ;u32 l, h; +if (!cpu_has_apic || disable_apic) +return ; +/* Thermal monitoring depends on ACPI and clock modulation*/ if (!cpu_has (c,X86_FEATURE_ACPI ) || !cpu_has (c,X86_FEATURE_ACC ))return ;
Signature · 1 line
[email protected] -- Speaking for myself only.
Quoted 19 lines · Andi Kleen
Quoted 7 lines · Johannes Stezenbach
Call Trace: [<c10248c1>] warn_slowpath_common+0x60/0x90 [<c10248fe>] warn_slowpath_null+0xd/0x10 [<c1013139>] native_apic_write_dummy+0x2d/0x39 [<c100dcd2>] intel_init_thermal+0xb6/0x144 [<c100d517>] ? mce_init+0x33/0xb0 [<c100db4b>] mce_intel_feature_init+0xb/0x4cQuoted 8 lines
[<c14fc31e>] mcheck_init+0x1e2/0x253 [<c14faef4>] identify_cpu+0x30b/0x31b [<c14d9af0>] identify_boot_cpu+0xd/0x23 [<c14d9b3c>] check_bugs+0xb/0xd4 [<c104f929>] ? delayacct_init+0x42/0x49 [<c14d493c>] start_kernel+0x25e/0x26d [<c14d430b>] i386_start_kernel+0x65/0x6a ---[ end trace 4eaa2a86a8e2da22 ]---
Quoted 1 line
The appended patch should remove the warning. Can you please test it?
It works (no more warning), but I feel I'm better off using "lapic" because it enables thermal monitoring and performance counters.
Thanks,
Johannes
Quoted 3 lines
Quoted 1 line
The appended patch should remove the warning. Can you please test it?
It works (no more warning), but I feel I'm better off using "lapic"
Thanks for testing.
Quoted 1 line
because it enables thermal monitoring and performance counters.
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.
-Andi
Signature · 1 line
[email protected] -- Speaking for myself only.
Quoted 6 lines · Andi Kleen
Quoted 3 lines
Quoted 1 line
The appended patch should remove the warning. Can you please test it?
It works (no more warning), but I feel I'm better off using "lapic"
Thanks for testing.
Quoted 7 lines
Quoted 1 line
because it enables thermal monitoring and performance counters.
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.
Johannes
Quoted 16 lines · Johannes Stezenbach
Quoted 6 lines · Andi Kleen
Quoted 3 lines
Quoted 1 line
The appended patch should remove the warning. Can you please test it?
It works (no more warning), but I feel I'm better off using "lapic"
Thanks for testing.
Quoted 8 lines
Quoted 1 line
because it enables thermal monitoring and performance counters.
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.
Quoted 4 lines
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.
Ingo
Quoted 10 lines · Ingo Molnar
Quoted 9 lines · Johannes Stezenbach
Quoted 7 lines · Andi Kleen
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.
Quoted 8 lines
Quoted 4 lines
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
# ./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
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 oprofiledLooks plausible.
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 ]---
Thanks
Johannes
Quoted 1 line
But in demsg I got this:
AFAIK that's already fixed. cc Robert to confirm. Not sure if the fix made it into 2.6.31 though?
-Andi
Quoted 36 lines
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 ]---Thanks
Johannes
Signature · 1 line
[email protected] -- Speaking for myself only.
Quoted 3 lines · Andi Kleen
Quoted 1 line
But in demsg I got this:
AFAIK that's already fixed. cc Robert to confirm. Not sure if the fix made it into 2.6.31 though?
The warning I fixed was in rb_advance_reader(). Fix is already upstream:
193df82 ring-buffer: Fix advance of reader in rb_buffer_peek()
But this seems to be different, a time stamp issue?
CC'ing Steve.
-Robert
Quoted 43 lines
-Andi
Quoted 36 lines
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 ]---Thanks
JohannesSignature · 1 line
[email protected] -- Speaking for myself only.
Signature · 3 lines
Advanced Micro Devices, Inc. Operating System Research Center email: [email protected]
Quoted 33 lines · Johannes Stezenbach
Quoted 10 lines · Ingo Molnar
Quoted 9 lines · Johannes Stezenbach
Quoted 7 lines · Andi Kleen
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.
Quoted 8 lines
Quoted 4 lines
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 truePerformance 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
Quoted 1 line
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?
Quoted 25 lines
# ./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
Quoted 1 line
^C
Ok, this looks normal.
Quoted 13 lines
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
Quoted 1 line
Looks plausible.
Yeah.
Quoted 24 lines
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]
Quoted 8 lines
[<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
Quoted 15 lines · Ingo Molnar
Quoted 14 lines · Johannes Stezenbach
# ./perf stat truePerformance 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
Quoted 5 lines
Quoted 1 line
0.001265524 seconds time elapsedThat looks almost normal - except for cache-references and cache-misses that is not counted. Could you send the
/proc/cpuinfoinfo please?
# cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 13 model name : Intel(R) Pentium(R) M processor 1.80GHz stepping : 6 cpu MHz : 600.000 cache size : 2048 KB fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 2 wp : yes flags : fpu vme de pse tsc msr mce cx8 apic sep mtrr pge mca cmov clflush dts acpi mmx fxsr sse sse2 ss tm pbe bts est tm2 bogomips : 1196.15 clflush size : 64 power management:
Quoted 2 lines
The warning is probably harmless - oprofile sampling still works fine, right?
I haven't done much testing so far, but so far it looks promising.
Could the warning be caused by the cpufreq ondemand governor? ISTR that one should switch to the performance governor before doing any profiling, but I forgot for this test.
Johannes
Quoted 22 lines · Johannes Stezenbach
Quoted 15 lines · Ingo Molnar
Quoted 14 lines · Johannes Stezenbach
# ./perf stat truePerformance 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-missesQuoted 5 lines
Quoted 1 line
0.001265524 seconds time elapsedThat looks almost normal - except for cache-references and cache-misses that is not counted. Could you send the
/proc/cpuinfoinfo please?
Quoted 6 lines
# cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 13 model name : Intel(R) Pentium(R) M processor 1.80GHz
ah, yes. There's no cache-references/misses, because in arch/x86/kernel/cpu/perf_counter.c we have two zero entries:
static const u64 p6_perfmon_event_map[] =
{
[PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, <---------- [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, <---------- [PERF_COUNT_HW_BRANCH_INSTRUCTIONS] = 0x00c4, [PERF_COUNT_HW_BRANCH_MISSES] = 0x00c5, [PERF_COUNT_HW_BUS_CYCLES] = 0x0062,
};
i.e. PERF_COUNT_HW_CACHE_REFERENCES and PERF_COUNT_HW_CACHE_MISSES is not filled in yet.
Could you try something like:
perf stat -e r0f2e true
(0x2e: L2 requests, 0x0f: all units)
if i checked the docs right that counter would give us L2 cache stats - does it display non-zero values?
Quoted 17 lines
stepping : 6
cpu MHz : 600.000
cache size : 2048 KBfdiv_bug: nohlt_bug: nof00f_bug: nocoma_bug: no
fpu : yesfpu_exception: yes
cpuid level : 2
wp : yes
flags : fpu vme de pse tsc msr mce cx8 apic sep mtrr pge mca cmov clflush dts acpi mmx fxsr sse sse2 ss tm pbe bts est tm2
bogomips : 1196.15
clflush size : 64
power management:
Quoted 8 lines
Quoted 2 lines
The warning is probably harmless - oprofile sampling still works fine, right?
I haven't done much testing so far, but so far it looks promising.
Could the warning be caused by the cpufreq ondemand governor? ISTR that one should switch to the performance governor before doing any profiling, but I forgot for this test.
there might be a connection - it could in theory cause sched_clock() transients and confuse the ring-buffer time-stamping.
Ingo
Quoted 26 lines · Ingo Molnar
Quoted 7 lines · Johannes Stezenbach
# cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 13 model name : Intel(R) Pentium(R) M processor 1.80GHzah, yes. There's no cache-references/misses, because in
arch/x86/kernel/cpu/perf_counter.cwe have two zero entries:static const u64 p6_perfmon_event_map[] =
{[PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, <---------- [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, <---------- [PERF_COUNT_HW_BRANCH_INSTRUCTIONS] = 0x00c4, [PERF_COUNT_HW_BRANCH_MISSES] = 0x00c5, [PERF_COUNT_HW_BUS_CYCLES] = 0x0062,};
i.e.
PERF_COUNT_HW_CACHE_REFERENCESandPERF_COUNT_HW_CACHE_MISSESis not filled in yet.
Quoted 8 lines
Could you try something like:
perf stat -e r0f2e true
(
0x2e: L2 requests,0x0f: all units)if i checked the docs right that counter would give us L2 cache stats - does it display non-zero values?
# ./perf stat -e r0f2e true
Performance counter stats for 'true':
10584 raw 0xf2e
0.001159924 seconds time elapsedThe number also increases for larger programs than "true".
According to /usr/share/oprofile/i386/p6_mobile/events and
http://oprofile.sourceforge.net/docs/intel-p6-mobile-events.php0x2e + 0x0f is "L2 requests, all units", but I couldn't say how to count cache references vs. misses. Or does it work with unit mask 0x0e vs. 0x01?
# ./perf stat -e r0e2e true
Performance counter stats for 'true':
10147 raw 0xe2e
0.001121651 seconds time elapsed# ./perf stat -e r012e true
Performance counter stats for 'true':
468 raw 0x12e
0.001130870 seconds time elapsedQuoted 6 lines
Quoted 3 lines
Could the warning be caused by the cpufreq ondemand governor? ISTR that one should switch to the performance governor before doing any profiling, but I forgot for this test.
there might be a connection - it could in theory cause
sched_clock()transients and confuse the ring-buffer time-stamping.
I'll try tomorrow after a fresh boot if the warning also appears with the performance governor.
Thanks
Johannes
PATCH 1/1 cache-miss and cache-refs events on P6-mobile CPUs
Quoted 60 lines · Johannes Stezenbach
Quoted 26 lines · Ingo Molnar
Quoted 7 lines · Johannes Stezenbach
# cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 13 model name : Intel(R) Pentium(R) M processor 1.80GHzah, yes. There's no cache-references/misses, because in
arch/x86/kernel/cpu/perf_counter.cwe have two zero entries:static const u64 p6_perfmon_event_map[] =
{[PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, <---------- [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, <---------- [PERF_COUNT_HW_BRANCH_INSTRUCTIONS] = 0x00c4, [PERF_COUNT_HW_BRANCH_MISSES] = 0x00c5, [PERF_COUNT_HW_BUS_CYCLES] = 0x0062,};
i.e.
PERF_COUNT_HW_CACHE_REFERENCESandPERF_COUNT_HW_CACHE_MISSESis not filled in yet.Quoted 8 lines
Could you try something like:
perf stat -e r0f2e true
(
0x2e: L2 requests,0x0f: all units)if i checked the docs right that counter would give us L2 cache stats - does it display non-zero values?
# ./perf stat -e r0f2e truePerformance counter stats for 'true':
10584 raw 0xf2e 0.001159924 seconds time elapsedThe number also increases for larger programs than "true".
According to
/usr/share/oprofile/i386/p6_mobile/eventsand
http://oprofile.sourceforge.net/docs/intel-p6-mobile-events.php0x2e+0x0fis "L2 requests, all units", but I couldn't say how to count cache references vs. misses. Or does it work with unit mask0x0evs.0x01?# ./perf stat -e r0e2e truePerformance counter stats for 'true':
10147 raw 0xe2e 0.001121651 seconds time elapsed
Quoted 7 lines
# ./perf stat -e r012e truePerformance counter stats for 'true':
468 raw 0x12e 0.001130870 seconds time elapsed
Ok. That definitely looks like the right event to use.
Could you try the patch below, does it do the trick? Note, since there's just two generic counters and perf stat uses four counters, you'll need to run longer commands than 'true' or something like:
perf stat -a sleep 1
or:
perf stat --repeat 10 /bin/ls -R /usr/bin >/dev/null
to get all counters excercised and time-shared on your CPU.
Ingo
-------------->
Subject: perf_counter, x86: Add generic cache events to P6-mobile CPUs
From: Ingo Molnar <[email protected]>
Date: Tue Aug 11 10:26:33 CEST 2009
Johannes Stezenbach reported that 'perf stat' does not count cache-miss and cache-references events on his Pentium-M based laptop.
Add the events.
--- arch/x86/kernel/cpu/perf_counter.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
arch/x86/kernel/cpu/perf_counter.c +2 -2
@@ -116,8 +116,8 @@ static const u64 p6_perfmon_event_map[] { [PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, - [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, - [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, + [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0f2e, + [PERF_COUNT_HW_CACHE_MISSES] = 0x012e, [PERF_COUNT_HW_BRANCH_INSTRUCTIONS] = 0x00c4, [PERF_COUNT_HW_BRANCH_MISSES] = 0x00c5, [PERF_COUNT_HW_BUS_CYCLES] = 0x0062,
Re: [patch] cache-miss and cache-refs events on P6-mobile CPUs
arch/x86/kernel/cpu/perf_counter.c static const u64 p6_perfmon_event_map[] · line 120
Quoted 8 lines · Ingo Molnar
arch/x86/kernel/cpu/perf_counter.c +2
-2@@ -116,8 +116,8 @@ static const u64 p6_perfmon_event_map[] { [PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, - [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, - [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, + [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0f2e, + [PERF_COUNT_HW_CACHE_MISSES] = 0x012e,
2e is total numer of L2 events,
0f is all mesi states
01 is invalid states
Yes they are numbers, but no they are not full cache refs and misses.
I don't think this is a good patch.
Re: [patch] cache-miss and cache-refs events on P6-mobile CPUs
Quoted 13 lines · Peter Zijlstra
arch/x86/kernel/cpu/perf_counter.c static const u64 p6_perfmon_event_map[] · line 120
Quoted 8 lines · Ingo Molnar
arch/x86/kernel/cpu/perf_counter.c +2
-2@@ -116,8 +116,8 @@ static const u64 p6_perfmon_event_map[] { [PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, - [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, - [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, + [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0f2e, + [PERF_COUNT_HW_CACHE_MISSES] = 0x012e,2e is total numer of L2 events,
Quoted 2 lines
0f is all mesi states
01 is invalid states
here's Intel's own description:
I_STATE 0x01 Counts how many times requests miss the cache.
MESI 0x0F Counts how many times cache lines in any state are accessed.
so it's pretty close in practice. The only counts that are a bit inapplicable are fetches/prefetches it initiates on its own (they are included here) - but those too are related to the workload in general, so it's good as an approximation.
It's definitely better than 0x00 IMO. What do you think?
Ingo
Re: [patch] cache-miss and cache-refs events on P6-mobile CPUs
Quoted 23 lines · Ingo Molnar
Quoted 13 lines · Peter Zijlstra
arch/x86/kernel/cpu/perf_counter.c static const u64 p6_perfmon_event_map[] · line 120
Quoted 8 lines · Ingo Molnar
arch/x86/kernel/cpu/perf_counter.c +2
-2@@ -116,8 +116,8 @@ static const u64 p6_perfmon_event_map[] { [PERF_COUNT_HW_CPU_CYCLES] = 0x0079, [PERF_COUNT_HW_INSTRUCTIONS] = 0x00c0, - [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0000, - [PERF_COUNT_HW_CACHE_MISSES] = 0x0000, + [PERF_COUNT_HW_CACHE_REFERENCES] = 0x0f2e, + [PERF_COUNT_HW_CACHE_MISSES] = 0x012e,2e is total numer of L2 events,
Quoted 2 lines
0f is all mesi states
01 is invalid stateshere's Intel's own description:
I_STATE0x01Counts how many times requests miss the cache.
MESI0x0FCounts how many times cache lines in any state are accessed.
Quoted 6 lines
so it's pretty close in practice. The only counts that are a bit inapplicable are fetches/prefetches it initiates on its own (they are included here) - but those too are related to the workload in general, so it's good as an approximation.
It's definitely better than
0x00IMO. What do you think?
Well, if they say so. I was thinking that counting I states would count invalidates due to remote S->{E,M} transitions and invpg ins' and such.
And hitting an invalidated line is a whole different thing than plain missing it due to it not being present.
Anyway, if this is the Intel recommended thing for cache misses, who am I to argue.
Re: [patch] cache-miss and cache-refs events on P6-mobile CPUs
In reply to Ingo MolnarQuoted 5 lines · Ingo Molnar
Could you try the patch below, does it do the trick? Note, since there's just two generic counters and perf stat uses four counters, you'll need to run longer commands than 'true' or something like:
Quoted 7 lines
perf stat -a sleep 1
or:
perf stat --repeat 10 /bin/ls -R /usr/bin >/dev/nullto get all counters excercised and time-shared on your CPU.
OK, here are the results:
# ./perf stat -a true
Performance counter stats for 'true':
1.332145 task-clock-msecs # 1.057 CPUs
4 context-switches # 0.003 M/sec
0 CPU-migrations # 0.000 M/sec
121 page-faults # 0.091 M/sec
788333 cycles # 591.777 M/sec
610408 instructions # 0.774 IPC
<not counted> cache-references
<not counted> cache-misses 0.001260775 seconds time elapsed
# ./perf stat -a sleep 1
Performance counter stats for 'sleep 1':
1001.358010 task-clock-msecs # 1.000 CPUs
253 context-switches # 0.000 M/sec
0 CPU-migrations # 0.000 M/sec
145 page-faults # 0.000 M/sec
8841883 cycles # 8.830 M/sec (scaled from 85.04%)
6361047 instructions # 0.719 IPC (scaled from 78.03%)
801847 cache-references # 0.801 M/sec (scaled from 14.96%)
16925 cache-misses # 0.017 M/sec (scaled from 21.97%)1.001540692 seconds time elapsed
# ./perf stat --repeat 10 /bin/ls -R /usr/bin >/dev/null
Performance counter stats for '/bin/ls -R /usr/bin' (10 runs):
8.642859 task-clock-msecs # 0.939 CPUs ( +- 2.382% )
1 context-switches # 0.000 M/sec ( +- 0.000% )
0 CPU-migrations # 0.000 M/sec ( +- 0.000% )
375 page-faults # 0.043 M/sec ( +- 0.000% )
14796621 cycles # 1712.005 M/sec ( +- 0.306% )
15526008 instructions # 1.049 IPC ( +- 0.020% )
<not counted> cache-references
<not counted> cache-misses 0.009207932 seconds time elapsed ( +- 4.020% )
# ./perf stat --repeat 10 /bin/ls -lR /usr/bin >/dev/null
Performance counter stats for '/bin/ls -lR /usr/bin' (10 runs):
49.894190 task-clock-msecs # 0.762 CPUs ( +- 8.231% )
45 context-switches # 0.001 M/sec ( +- 52.174% )
0 CPU-migrations # 0.000 M/sec ( +- 0.000% )
476 page-faults # 0.010 M/sec ( +- 0.000% )
81036819 cycles # 1624.173 M/sec ( +- 3.166% ) (scaled from 96.03%)
88822455 instructions # 1.096 IPC ( +- 2.108% ) (scaled from 96.42%)
573228 cache-references # 11.489 M/sec ( +- 37.947% )
<not counted> cache-misses 0.065464625 seconds time elapsed ( +- 19.349% )
# ./perf stat --repeat 10 /bin/ls -R /usr/lib >/dev/null
Performance counter stats for '/bin/ls -R /usr/lib' (10 runs):
136.771643 task-clock-msecs # 0.075 CPUs ( +- 19.292% )
757 context-switches # 0.006 M/sec ( +- 56.332% )
0 CPU-migrations # 0.000 M/sec ( +- 0.000% )
343 page-faults # 0.003 M/sec ( +- 0.000% )
173125500 cycles # 1265.800 M/sec ( +- 5.034% ) (scaled from 78.21%)
174597635 instructions # 1.009 IPC ( +- 1.829% ) (scaled from 78.34%)
2441413 cache-references # 17.850 M/sec ( +- 18.289% ) (scaled from 21.79%)
21112 cache-misses # 0.154 M/sec ( +- 11.183% ) (scaled from 21.66%)1.824204481 seconds time elapsed ( +- 29.781% )
Johannes
Re: [patch] cache-miss and cache-refs events on P6-mobile CPUs
Quoted 89 lines · Johannes Stezenbach
Quoted 5 lines · Ingo Molnar
Could you try the patch below, does it do the trick? Note, since there's just two generic counters and perf stat uses four counters, you'll need to run longer commands than 'true' or something like:
Quoted 7 lines
perf stat -a sleep 1
or:
perf stat --repeat 10 /bin/ls -R /usr/bin >/dev/nullto get all counters excercised and time-shared on your CPU.
OK, here are the results:
# ./perf stat -a truePerformance counter stats for 'true':
1.332145 task-clock-msecs # 1.057 CPUs 4 context-switches # 0.003 M/sec 0 CPU-migrations # 0.000 M/sec 121 page-faults # 0.091 M/sec 788333 cycles # 591.777 M/sec 610408 instructions # 0.774 IPC <not counted> cache-references <not counted> cache-misses0.001260775 seconds time elapsed# ./perf stat -a sleep 1Performance counter stats for 'sleep 1':
1001.358010 task-clock-msecs # 1.000 CPUs 253 context-switches # 0.000 M/sec 0 CPU-migrations # 0.000 M/sec 145 page-faults # 0.000 M/sec 8841883 cycles # 8.830 M/sec (scaled from 85.04%) 6361047 instructions # 0.719 IPC (scaled from 78.03%) 801847 cache-references # 0.801 M/sec (scaled from 14.96%) 16925 cache-misses # 0.017 M/sec (scaled from 21.97%)1.001540692 seconds time elapsed# ./perf stat --repeat 10 /bin/ls -R /usr/bin >/dev/nullPerformance counter stats for '
/bin/ls-R/usr/bin' (10 runs):8.642859 task-clock-msecs # 0.939 CPUs ( +- 2.382% ) 1 context-switches # 0.000 M/sec ( +- 0.000% ) 0 CPU-migrations # 0.000 M/sec ( +- 0.000% ) 375 page-faults # 0.043 M/sec ( +- 0.000% ) 14796621 cycles # 1712.005 M/sec ( +- 0.306% ) 15526008 instructions # 1.049 IPC ( +- 0.020% ) <not counted> cache-references <not counted> cache-misses0.009207932 seconds time elapsed ( +- 4.020% )# ./perf stat --repeat 10 /bin/ls -lR /usr/bin >/dev/nullPerformance counter stats for '
/bin/ls-lR/usr/bin' (10 runs):49.894190 task-clock-msecs # 0.762 CPUs ( +- 8.231% ) 45 context-switches # 0.001 M/sec ( +- 52.174% ) 0 CPU-migrations # 0.000 M/sec ( +- 0.000% ) 476 page-faults # 0.010 M/sec ( +- 0.000% ) 81036819 cycles # 1624.173 M/sec ( +- 3.166% ) (scaled from 96.03%) 88822455 instructions # 1.096 IPC ( +- 2.108% ) (scaled from 96.42%) 573228 cache-references # 11.489 M/sec ( +- 37.947% ) <not counted> cache-misses0.065464625 seconds time elapsed ( +- 19.349% )# ./perf stat --repeat 10 /bin/ls -R /usr/lib >/dev/nullPerformance counter stats for '
/bin/ls-R/usr/lib' (10 runs):136.771643 task-clock-msecs # 0.075 CPUs ( +- 19.292% ) 757 context-switches # 0.006 M/sec ( +- 56.332% ) 0 CPU-migrations # 0.000 M/sec ( +- 0.000% ) 343 page-faults # 0.003 M/sec ( +- 0.000% ) 173125500 cycles # 1265.800 M/sec ( +- 5.034% ) (scaled from 78.21%) 174597635 instructions # 1.009 IPC ( +- 1.829% ) (scaled from 78.34%) 2441413 cache-references # 17.850 M/sec ( +- 18.289% ) (scaled from 21.79%) 21112 cache-misses # 0.154 M/sec ( +- 11.183% ) (scaled from 21.66%)
Quoted 1 line
1.824204481 seconds time elapsed ( +- 29.781% )
Ok, this all looks pretty good!
Ingo
Quoted 7 lines · Johannes Stezenbach
Quoted 6 lines · Ingo Molnar
Quoted 4 lines · Johannes Stezenbach
Could the warning be caused by the cpufreq ondemand governor? ISTR that one should switch to the performance governor before doing any profiling, but I forgot for this test.
Quoted 5 lines
Quoted 2 lines
there might be a connection - it could in theory cause
sched_clock()transients and confuse the ring-buffer time-stamping.I'll try tomorrow after a fresh boot if the warning also appears with the performance governor.
Nope, cpufreq was not the culprit. The "Delta way too big!" warning in rb_reserve_next_event() happens after suspend-to-RAM.
Johannes
Quoted 8 lines · Johannes Stezenbach
Quoted 7 lines · Johannes Stezenbach
Quoted 6 lines · Ingo Molnar
Quoted 4 lines · Johannes Stezenbach
Could the warning be caused by the cpufreq ondemand governor? ISTR that one should switch to the performance governor before doing any profiling, but I forgot for this test.
Quoted 8 lines
Quoted 5 lines
Quoted 2 lines
there might be a connection - it could in theory cause
sched_clock()transients and confuse the ring-buffer time-stamping.I'll try tomorrow after a fresh boot if the warning also appears with the performance governor.
Nope, cpufreq was not the culprit. The "Delta way too big!" warning in
rb_reserve_next_event()happens after suspend-to-RAM.
Yeah, the ring buffer expects the time delta of two different events on the same page to be less than 2^59 nanosecs apart. But something must have screwed things up, since 2^59 nanosecs is 6671 days (18 years).
Perhaps coming out of suspend to ram changes the timestamp? Does it reset the result of sched_clock?
-- Steve
Ingo Molnar
Tested-by Johannes StezenbachRe: *PING* [PATCH]: x86: mce: fix mce warning with disabled lapic
In reply to Andi KleenQuoted 2 lines · Andi Kleen
*PING* can someone please take the patch in there and process the other suggestions?
Firstly, a basic patch submission technical matter: could you please stop spamming maintainers of the x86/MCE code with such '*PING*' private mails, for patches you never properly submitted to begin with?
The proper way to submit an upstream kernel fix, as you should well be aware of, is to send a patch with a proper title and to Cc: it to lkml and the maintainers affected. You never did that, you only posted a for-testing patch into a discussion. Please stop this self-important posturing, it's somewhat annoying.
Also, another, patch log quality issue, please credit Johannes properly. You put this into the changelog:
Quoted 5 lines
Originally reported by Johannes Stezenbach
This is a 2.6.31 candidate because it fixes a regression.
Signed-off-by Andi Kleen <[email protected]>
The proper way is to put this into the changelog:
And given that Johannes also tested the patch, another line of:
Would be appropriate as well.
Thirdly, we can do better with the fix itself too:
arch/x86/kernel/cpu/mcheck/therm_throt.c void intel_init_thermal(struct cpuinfo_x · line 244
Quoted 11 lines
+++
linux/arch/x86/kernel/cpu/mcheck/therm_throt.carch/x86/kernel/cpu/mcheck/therm_throt.c +3
-0@@ -236,6 +236,9 @@ void intel_init_thermal(struct cpuinfo_xint tm2 =0 ;u32 l, h; +if (!cpu_has_apic || disable_apic) +return ; +/* Thermal monitoring depends on ACPI and clock modulation*/ if (!cpu_has (c,X86_FEATURE_ACPI ) || !cpu_has (c,X86_FEATURE_ACC ))return ;
we already have that X86_FEATURE_ACPI and X86_FEATURE_ACC check and a return statement. Would be better to expand that with the APIC checks. Plus update the comment to also mention APIC as a requirement plus fix the small error in the comment too while at it.
If these problems are fixed i'll apply the fix to tip:x86/urgent.
Thanks,
Ingo