Hello
Let the fuzzer running a long time on 5.19-rc1 and after a few weeks it
triggered this weird trace. It is repeatable (although I haven't
narrowed down exactly what's causing it).
It's odd in that it just dumps a <TASK>, it doesn't provide any info on
what the actual trigger is.
This is on a Haswell machine.
[2611569.407088] Call Trace:
[2611569.407092] <TASK>
[2611569.407093] intel_pmu_lbr_restore+0x9a/0x1f0
[2611569.407100] intel_pmu_lbr_sched_task+0x91/0x1c0
[2611569.407103] __perf_event_task_sched_in+0x1cd/0x240
[2611569.407107] ? __perf_event_task_sched_out+0x75/0x5c0
[2611569.407109] finish_task_switch.isra.0+0x188/0x2a0
[2611569.407114] ? __switch_to+0x112/0x430
[2611569.407119] __schedule+0x2cf/0x10d0
[2611569.407123] ? __sysvec_irq_work+0x5b/0xc0
[2611569.407127] schedule+0x4e/0xb0
[2611569.407129] schedule_timeout+0x115/0x150
[2611569.407132] ? schedule_timeout+0x115/0x150
[2611569.407135] ? _raw_spin_unlock_irqrestore+0x23/0x40
[2611569.407138] ? preempt_count_add+0x68/0xa0
[2611569.407141] ? preempt_count_add+0x68/0xa0
[2611569.407144] __wait_for_common+0x93/0x1a0
[2611569.407146] ? usleep_range_state+0x90/0x90
[2611569.407149] __wait_rcu_gp+0x112/0x120
[2611569.407152] synchronize_rcu+0xc8/0xe0
[2611569.407156] ? note_gp_changes+0x80/0x80
[2611569.407159] perf_trace_event_unreg.isra.0+0x37/0x90
[2611569.407163] perf_trace_destroy+0x38/0x50
[2611569.407165] _free_event+0xf9/0x3d0
[2611569.407167] perf_event_release_kernel+0x279/0x2d0
[2611569.407170] perf_release+0x11/0x20
[2611569.407172] __fput+0x8c/0x240
[2611569.407175] task_work_run+0x5c/0x90
[2611569.407180] exit_to_user_mode_prepare+0x125/0x130
[2611569.407183] syscall_exit_to_user_mode+0x22/0x40
[2611569.407185] ? __x64_sys_close+0xd/0x40
[2611569.407189] do_syscall_64+0x48/0xc0
[2611569.407193] entry_SYSCALL_64_after_hwframe+0x46/0xb0
[2611569.407198] RIP: 0033:0x7f92e4813cc3
[2611569.407200] Code: e9 37 ff ff ff e8 ad ef 01 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 03 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 45 c3 0f 1f 40 00 48 83 ec 18 89 7c 24 0c e8
[2611569.407202] RSP: 002b:00007fffc243bb98 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
[2611569.407205] RAX: 0000000000000000 RBX: 000000000000000c RCX: 00007f92e4813cc3
[2611569.407207] RDX: 0000000000005be0 RSI: 00007fffc243bb74 RDI: 0000000000000048
[2611569.407208] RBP: 00007fffc243bbc0 R08: 00007f92e48f7234 R09: 00007f92e48f7240
[2611569.407209] R10: 0000000000000000 R11: 0000000000000246 R12: 000056355ea124f0
[2611569.407210] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[2611569.407212] </TASK>
On Wed, 6 Jul 2022, Vince Weaver wrote:
> Let the fuzzer running a long time on 5.19-rc1 and after a few weeks it
> triggered this weird trace. It is repeatable (although I haven't
> narrowed down exactly what's causing it).
>
> It's odd in that it just dumps a <TASK>, it doesn't provide any info on
> what the actual trigger is.
>
> This is on a Haswell machine.
I bumped up to current git and managed to trigger this again, this time
it actually managed to print the error message.
[ 7763.384369] unchecked MSR access error: WRMSR to 0x689 (tried to write 0x1fffffff8101349e) at rIP: 0xffffffff810704a4 (native_write_msr+0x4/0x20)
[ 7763.397420] Call Trace:
[ 7763.399881] <TASK>
[ 7763.401994] intel_pmu_lbr_restore+0x9a/0x1f0
[ 7763.406363] intel_pmu_lbr_sched_task+0x91/0x1c0
[ 7763.410992] __perf_event_task_sched_in+0x1cd/0x240
[ 7763.415879] ? __perf_event_task_sched_out+0x75/0x5c0
[ 7763.420939] finish_task_switch.isra.0+0x15b/0x2a0
[ 7763.425740] ? __switch_to+0x112/0x430
[ 7763.429503] __schedule+0x2cf/0x10d0
[ 7763.433088] ? send_signal_locked+0xc8/0x130
[ 7763.437364] schedule+0x4e/0xb0
[ 7763.440518] do_wait+0x15b/0x2f0
[ 7763.443757] kernel_wait4+0xa6/0x140
[ 7763.447337] ? thread_group_exited+0x60/0x60
[ 7763.451608] do_syscall_64+0x3b/0xc0
[ 7763.455199] entry_SYSCALL_64_after_hwframe+0x46/0xb0
[ 7763.460259] RIP: 0033:0x7f9063feba26
[ 7763.463838] Code: ff e9 0e 00 00 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 49 89 ca 64 8b 04 25 18 00 00 00 85 c0 75 11 b8 3d 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 5a c3 90 48 83 ec 28 89 54 24 14 48 89 74 24
[ 7763.482587] RSP: 002b:00007ffca3875c08 EFLAGS: 00000246 ORIG_RAX: 000000000000003d
[ 7763.490161] RAX: ffffffffffffffda RBX: 000000000000000c RCX: 00007f9063feba26
[ 7763.497303] RDX: 0000000000000000 RSI: 00007ffca3875c1c RDI: 0000000000002214
[ 7763.504441] RBP: 00007ffca3875c20 R08: 00007f90640f321c R09: 00007f90640f3240
[ 7763.511577] R10: 0000000000000000 R11: 0000000000000246 R12: 000055d6ce93c4f0
[ 7763.518718] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 7763.525850] </TASK>
On 2022-07-08 12:13 p.m., Vince Weaver wrote:
> On Wed, 6 Jul 2022, Vince Weaver wrote:
>
>> Let the fuzzer running a long time on 5.19-rc1 and after a few weeks it
>> triggered this weird trace. It is repeatable (although I haven't
>> narrowed down exactly what's causing it).
>>
>> It's odd in that it just dumps a <TASK>, it doesn't provide any info on
>> what the actual trigger is.
>>
>> This is on a Haswell machine.
>
> I bumped up to current git and managed to trigger this again, this time
> it actually managed to print the error message.
>
> [ 7763.384369] unchecked MSR access error: WRMSR to 0x689 (tried to write 0x1fffffff8101349e) at rIP: 0xffffffff810704a4 (native_write_msr+0x4/0x20)
The 0x689 is a valid LBR register, which is MSR_LASTBRANCH_9_FROM_IP.
The issue should be caused by the known TSX bug, which is mentioned in
the commit 9fc9ddd61e0 ("perf/x86/intel: Fix MSR_LAST_BRANCH_FROM_x bug
when no TSX"). It looks like the TSX support has been deactivated,
however the quirk in the commit isn't applied for some reason.
To apply the quirk, perf relies on the boot CPU's flag and LBR format.
static inline bool lbr_from_signext_quirk_needed(void)
{
bool tsx_support = boot_cpu_has(X86_FEATURE_HLE) ||
boot_cpu_has(X86_FEATURE_RTM);
return !tsx_support && x86_pmu.lbr_has_tsx;
}
Could you please share the value of the PERF_CAPABILITIES MSR 0x00000345
of the machine?
I'd like to double check whether the LBR fromat is correct. 0x5 is expected.
If the LBR format is correct, maybe the boot CPU's flag is not cleared
when the TSX support is deactivated.
I noticed that Pawan recently had several TSX patches merged which may
impact the flags.
400331f8ffa3 ("x86/tsx: Disable TSX development mode at boot")
258f3b8c3210 ("x86/tsx: Use MSR_TSX_CTRL to clear CPUID bits")
If you only observe the issue with the latest kernel, you may want to
revert the above two patches and see if it helps.
Thanks,
Kan
> [ 7763.397420] Call Trace:
> [ 7763.399881] <TASK>
> [ 7763.401994] intel_pmu_lbr_restore+0x9a/0x1f0
> [ 7763.406363] intel_pmu_lbr_sched_task+0x91/0x1c0
> [ 7763.410992] __perf_event_task_sched_in+0x1cd/0x240
> [ 7763.415879] ? __perf_event_task_sched_out+0x75/0x5c0
> [ 7763.420939] finish_task_switch.isra.0+0x15b/0x2a0
> [ 7763.425740] ? __switch_to+0x112/0x430
> [ 7763.429503] __schedule+0x2cf/0x10d0
> [ 7763.433088] ? send_signal_locked+0xc8/0x130
> [ 7763.437364] schedule+0x4e/0xb0
> [ 7763.440518] do_wait+0x15b/0x2f0
> [ 7763.443757] kernel_wait4+0xa6/0x140
> [ 7763.447337] ? thread_group_exited+0x60/0x60
> [ 7763.451608] do_syscall_64+0x3b/0xc0
> [ 7763.455199] entry_SYSCALL_64_after_hwframe+0x46/0xb0
> [ 7763.460259] RIP: 0033:0x7f9063feba26
> [ 7763.463838] Code: ff e9 0e 00 00 00 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 49 89 ca 64 8b 04 25 18 00 00 00 85 c0 75 11 b8 3d 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 5a c3 90 48 83 ec 28 89 54 24 14 48 89 74 24
> [ 7763.482587] RSP: 002b:00007ffca3875c08 EFLAGS: 00000246 ORIG_RAX: 000000000000003d
> [ 7763.490161] RAX: ffffffffffffffda RBX: 000000000000000c RCX: 00007f9063feba26
> [ 7763.497303] RDX: 0000000000000000 RSI: 00007ffca3875c1c RDI: 0000000000002214
> [ 7763.504441] RBP: 00007ffca3875c20 R08: 00007f90640f321c R09: 00007f90640f3240
> [ 7763.511577] R10: 0000000000000000 R11: 0000000000000246 R12: 000055d6ce93c4f0
> [ 7763.518718] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> [ 7763.525850] </TASK>
>
On Mon, 11 Jul 2022, Liang, Kan wrote:
>
>
> On 2022-07-08 12:13 p.m., Vince Weaver wrote:
> > [ 7763.384369] unchecked MSR access error: WRMSR to 0x689 (tried to write 0x1fffffff8101349e) at rIP: 0xffffffff810704a4 (native_write_msr+0x4/0x20)
>
> The 0x689 is a valid LBR register, which is MSR_LASTBRANCH_9_FROM_IP.
> The issue should be caused by the known TSX bug, which is mentioned in
> the commit 9fc9ddd61e0 ("perf/x86/intel: Fix MSR_LAST_BRANCH_FROM_x bug
> when no TSX"). It looks like the TSX support has been deactivated,
> however the quirk in the commit isn't applied for some reason.
>
>
> To apply the quirk, perf relies on the boot CPU's flag and LBR format.
>
> static inline bool lbr_from_signext_quirk_needed(void)
> {
> bool tsx_support = boot_cpu_has(X86_FEATURE_HLE) ||
> boot_cpu_has(X86_FEATURE_RTM);
>
> return !tsx_support && x86_pmu.lbr_has_tsx;
> }
>
> Could you please share the value of the PERF_CAPABILITIES MSR 0x00000345
> of the machine?
> I'd like to double check whether the LBR fromat is correct. 0x5 is expected.
How would I do that? Just something like:
# rdmsr 0x00000345
32c4
or is it more involved than that?
Vince Weaver
[email protected]
On Mon, Jul 11, 2022 at 11:25:34AM -0400, Liang, Kan wrote:
>
>
>On 2022-07-08 12:13 p.m., Vince Weaver wrote:
>> On Wed, 6 Jul 2022, Vince Weaver wrote:
>>
>>> Let the fuzzer running a long time on 5.19-rc1 and after a few weeks it
>>> triggered this weird trace. It is repeatable (although I haven't
>>> narrowed down exactly what's causing it).
>>>
>>> It's odd in that it just dumps a <TASK>, it doesn't provide any info on
>>> what the actual trigger is.
>>>
>>> This is on a Haswell machine.
>>
>> I bumped up to current git and managed to trigger this again, this time
>> it actually managed to print the error message.
>>
>> [ 7763.384369] unchecked MSR access error: WRMSR to 0x689 (tried to write 0x1fffffff8101349e) at rIP: 0xffffffff810704a4 (native_write_msr+0x4/0x20)
>
>The 0x689 is a valid LBR register, which is MSR_LASTBRANCH_9_FROM_IP.
>The issue should be caused by the known TSX bug, which is mentioned in
>the commit 9fc9ddd61e0 ("perf/x86/intel: Fix MSR_LAST_BRANCH_FROM_x bug
>when no TSX"). It looks like the TSX support has been deactivated,
>however the quirk in the commit isn't applied for some reason.
>
>
>To apply the quirk, perf relies on the boot CPU's flag and LBR format.
>
>static inline bool lbr_from_signext_quirk_needed(void)
>{
> bool tsx_support = boot_cpu_has(X86_FEATURE_HLE) ||
> boot_cpu_has(X86_FEATURE_RTM);
>
> return !tsx_support && x86_pmu.lbr_has_tsx;
>}
>
>Could you please share the value of the PERF_CAPABILITIES MSR 0x00000345
>of the machine?
>I'd like to double check whether the LBR fromat is correct. 0x5 is expected.
>
>
>If the LBR format is correct, maybe the boot CPU's flag is not cleared
>when the TSX support is deactivated.
>I noticed that Pawan recently had several TSX patches merged which may
>impact the flags.
>400331f8ffa3 ("x86/tsx: Disable TSX development mode at boot")
>258f3b8c3210 ("x86/tsx: Use MSR_TSX_CTRL to clear CPUID bits")
>If you only observe the issue with the latest kernel, you may want to
>revert the above two patches and see if it helps.
Output of below would be helpful:
# grep "rtm\|hle" /proc/cpuinfo
ARCH_CAP
# rdmsr 0x10a
TSX_CTRL
# rdmsr 0x122
MCU_OPT_CTRL
# rdmsr 0x123
TSX_FORCE_ABORT
# rdmsr 0x10f
Please note, some of these MSRs may not exist on your platform.
Thanks,
Pawan
On 2022-07-11 5:13 p.m., Vince Weaver wrote:
> On Mon, 11 Jul 2022, Liang, Kan wrote:
>
>>
>>
>> On 2022-07-08 12:13 p.m., Vince Weaver wrote:
>>> [ 7763.384369] unchecked MSR access error: WRMSR to 0x689 (tried to write 0x1fffffff8101349e) at rIP: 0xffffffff810704a4 (native_write_msr+0x4/0x20)
>>
>> The 0x689 is a valid LBR register, which is MSR_LASTBRANCH_9_FROM_IP.
>> The issue should be caused by the known TSX bug, which is mentioned in
>> the commit 9fc9ddd61e0 ("perf/x86/intel: Fix MSR_LAST_BRANCH_FROM_x bug
>> when no TSX"). It looks like the TSX support has been deactivated,
>> however the quirk in the commit isn't applied for some reason.
>>
>>
>> To apply the quirk, perf relies on the boot CPU's flag and LBR format.
>>
>> static inline bool lbr_from_signext_quirk_needed(void)
>> {
>> bool tsx_support = boot_cpu_has(X86_FEATURE_HLE) ||
>> boot_cpu_has(X86_FEATURE_RTM);
>>
>> return !tsx_support && x86_pmu.lbr_has_tsx;
>> }
>>
>> Could you please share the value of the PERF_CAPABILITIES MSR 0x00000345
>> of the machine?
>> I'd like to double check whether the LBR fromat is correct. 0x5 is expected.
>
> How would I do that? Just something like:
> # rdmsr 0x00000345
> 32c4
>
Yes. It indicates that the LBR format is 4. That's expected for HSW.
(I made a mistake in the previous email. Skylake has format 5, not HSW.)
For the LBR format 4, the x86_pmu.lbr_has_tsx must be 1.
So it looks like an issue of the CPU flag.
Could you please collect the TSX information which Pawan mentioned in
the other thread?
Thanks,
Kan
> or is it more involved than that?
>
> Vince Weaver
> [email protected]
On Mon, 11 Jul 2022, Pawan Gupta wrote:
> Output of below would be helpful:
>
> # grep "rtm\|hle" /proc/cpuinfo
no results
> ARCH_CAP
> # rdmsr 0x10a
rdmsr: CPU 0 cannot read MSR 0x0000010a
> TSX_CTRL
> # rdmsr 0x122
rdmsr: CPU 0 cannot read MSR 0x00000122
> MCU_OPT_CTRL
> # rdmsr 0x123
0
> TSX_FORCE_ABORT
> # rdmsr 0x10f
rdmsr: CPU 0 cannot read MSR 0x0000010f
This is on a Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz
Family model stepping: 6/60/3
Vince
On Tue, Jul 12, 2022 at 03:39:56PM -0400, Vince Weaver wrote:
>On Mon, 11 Jul 2022, Pawan Gupta wrote:
>
>> Output of below would be helpful:
>>
>> # grep "rtm\|hle" /proc/cpuinfo
>
>no results
>
>> ARCH_CAP
>> # rdmsr 0x10a
>
>rdmsr: CPU 0 cannot read MSR 0x0000010a
>
>> TSX_CTRL
>> # rdmsr 0x122
>
>rdmsr: CPU 0 cannot read MSR 0x00000122
>
>> MCU_OPT_CTRL
>> # rdmsr 0x123
>
>0
>
>> TSX_FORCE_ABORT
>> # rdmsr 0x10f
>
>rdmsr: CPU 0 cannot read MSR 0x0000010f
It appears this CPU does not support TSX feature (or disabling TSX). If
the bug is easy to reproduce, bisecting can help.
Thanks,
Pawan
On Tue, 12 Jul 2022, Pawan Gupta wrote:
> On Tue, Jul 12, 2022 at 03:39:56PM -0400, Vince Weaver wrote:
> It appears this CPU does not support TSX feature (or disabling TSX). If
> the bug is easy to reproduce, bisecting can help.
I thought TSX was disabled via firmware update for all Haswell machines?
In any case, the fuzzer is triggering the
unchecked MSR access error: WRMSR to 0x689
in intel_pmu_lbr_restore. So either this is a false error and should be
disabled, or else it's a real issue and should be fixed.
Unfortunately the fuzzer can take up to a few days to trigger the message
(it's not easily repeatable) so doing a kernel bisect would take a very
long time.
Vince
On 2022-07-12 5:26 p.m., Vince Weaver wrote:
> On Tue, 12 Jul 2022, Pawan Gupta wrote:
>
>> On Tue, Jul 12, 2022 at 03:39:56PM -0400, Vince Weaver wrote:
>> It appears this CPU does not support TSX feature (or disabling TSX). If
>> the bug is easy to reproduce, bisecting can help.
>
> I thought TSX was disabled via firmware update for all Haswell machines?
>
> In any case, the fuzzer is triggering the
> unchecked MSR access error: WRMSR to 0x689
> in intel_pmu_lbr_restore. So either this is a false error and should be
> disabled, or else it's a real issue and should be fixed.
>
Could you please double check if the quirk can fix the issue on your
machine?
#Try write the exact same value from the error log to 0x689. The write
should fail.
wrmsr -p 0 0x689 0x1fffffff8101349e
#The quirk copy bits 59:60 to bits 61:62. The below write should succeed.
wrmsr -p 0 0x689 0x7fffffff8101349e
> Unfortunately the fuzzer can take up to a few days to trigger the message
> (it's not easily repeatable) so doing a kernel bisect would take a very
> long time.
>
The lbr_from_signext_quirk_needed() is only invoked at boot time. Maybe
we can dump some logs to understand which variable is not expected.
Could you please apply the below patch, reboot to the patched kernel and
share the dmesg log?
diff --git a/arch/x86/events/intel/lbr.c b/arch/x86/events/intel/lbr.c
index 13179f31fe10..50435ab627ad 100644
--- a/arch/x86/events/intel/lbr.c
+++ b/arch/x86/events/intel/lbr.c
@@ -300,6 +300,9 @@ static inline bool lbr_from_signext_quirk_needed(void)
bool tsx_support = boot_cpu_has(X86_FEATURE_HLE) ||
boot_cpu_has(X86_FEATURE_RTM);
+ pr_info("%s %s. LBR has tsx %d\n", boot_cpu_has(X86_FEATURE_HLE) ?
"HLE" : "NO HLE",
+ boot_cpu_has(X86_FEATURE_RTM) ? "RTM" : "NO RTM",
+ x86_pmu.lbr_has_tsx);
return !tsx_support && x86_pmu.lbr_has_tsx;
}
Thanks,
Kan
On Tue, 12 Jul 2022, Liang, Kan wrote:
>
> Could you please apply the below patch, reboot to the patched kernel and
> share the dmesg log?
here's the info with your patch applied:
[ 0.000000] microcode: microcode updated early to revision 0x28, date = 2019-11-12
...
[ 1.460296] NO HLE NO RTM. LBR has tsx 0
[ 1.468217] Haswell events, 16-deep LBR, full-width counters, Intel PMU driver.
[ 1.472292] ... version: 3
[ 1.476275] ... bit width: 48
[ 1.480275] ... generic registers: 4
[ 1.484276] ... value mask: 0000ffffffffffff
[ 1.488277] ... max period: 00007fffffffffff
[ 1.492277] ... fixed-purpose events: 3
[ 1.496271] ... event mask: 000000070000000f
Vince
On 2022-07-14 12:12 p.m., Vince Weaver wrote:
> On Tue, 12 Jul 2022, Liang, Kan wrote:
>
>>
>> Could you please apply the below patch, reboot to the patched kernel and
>> share the dmesg log?
>
> here's the info with your patch applied:
>
> [ 0.000000] microcode: microcode updated early to revision 0x28, date = 2019-11-12
> ...
> [ 1.460296] NO HLE NO RTM. LBR has tsx 0
Thanks.
The issue should be introduced by the commit 1ac7fd8159a8
("perf/x86/intel/lbr: Support LBR format V7").
The quirk is invoked before the intel_pmu_lbr_init(), which set the
x86_pmu.lbr_has_tsx.
I will send out a patch to fix it shortly.
Thanks,
Kan
> [ 1.468217] Haswell events, 16-deep LBR, full-width counters, Intel PMU driver.
> [ 1.472292] ... version: 3
> [ 1.476275] ... bit width: 48
> [ 1.480275] ... generic registers: 4
> [ 1.484276] ... value mask: 0000ffffffffffff
> [ 1.488277] ... max period: 00007fffffffffff
> [ 1.492277] ... fixed-purpose events: 3
> [ 1.496271] ... event mask: 000000070000000f
>
> Vince