perf_fuzzer causes reboot

So I'm not sure who exactly to report this to. Some perf people CC'd as I trigger it while using the perf_fuzzer.

This is with 3.14-rc3 on a core2 machine, although I've had the reboots happen throughout at least 3.14-rc*

I'm having a hard time coming up with a reproducible test case. Using the random seed that caused the below will cause the perf_fuzzer to segfault but not reboot.

The log isn't very helpful, it reboots so fast that the oops doesn't finish printing and the serial log just moves to the bootloader...

[ 4466.804123] BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
[ 4466.808014] IP: [<ffffffff81111783>] cache_reap+0x5e/0x1c5
[ 4466.808014] PGD 0 
[ 4466.808014] Oops: 0000 [#1] GNU GRUB  version 2.00-17

Quoted 10 lines · Vince Weaver

So I'm not sure who exactly to report this to. Some perf people CC'd as I trigger it while using the perf_fuzzer.

This is with 3.14-rc3 on a core2 machine, although I've had the reboots happen throughout at least 3.14-rc*

I'm having a hard time coming up with a reproducible test case. Using the random seed that caused the below will cause the perf_fuzzer to segfault but not reboot.

Quoted 7 lines

The log isn't very helpful, it reboots so fast that the oops doesn't finish printing and the serial log just moves to the bootloader...

[ 4466.804123] BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
[ 4466.808014] IP: [<ffffffff81111783>] cache_reap+0x5e/0x1c5
[ 4466.808014] PGD 0 
[ 4466.808014] Oops: 0000 [#1] GNU GRUB  version 2.00-17

Maybe related, this is on an x32-compiled binary.

When trying to reproduce the perf_fuzzer myseriously segfaults on what appears to be perfectly valid mmap'd perf ring-buffers.

(running under gdb)

Program received signal SIGSEGV, Segmentation fault. 0x0041efbb in __memset_sse2 ()

=> 0x0041efbb <+2203>: movdqa %xmm0,(%rdi)

rdi 0xf7f61000 4160098304

f7f61000-f7f72000 rw-s 00000000 00:08 4475 anon_inode:[perf_event]

So I'm not sure if somehow something is wrong with the page mapping, that makes a valid write fail and sometimes (possibly due to address space randomization) reboot the system?

So I changed the perf_fuzzer so when it randomly stomps all over the perf_event_mmap_page, it uses a constant value of 0xdeadbeef rather than a random value.

The result is below. The segfaults make a bit more sense now, it almost looks like what is happening is we are corrupting an address value somehow (head? tail?) and the kernel then uses the corrupt address
and writes to memory outside of the mmap ring buffer.

I still haven't figured out how to trigger this exactly, but you can see when over-written with 0xdeadbeef the memory address written to is consistently some small multiple of 0x120.

I imagine it would be a bad thing if it turned out to be possible to select what memory address got written to. Although since I've only reproduced this on x32 maybe it won't be possible to over-write the kernel; but I have seen this bug cause a reboot when the wrong thing got over-written.

[28002.850192] perf_fuzzer[7083]: segfault at 2be0 ip 000000000041efab
sp 00000000ff826748 error 6 in perf_fuzzer[400000+d1000]
[28639.769869] perf_fuzzer[7100]: segfault at 1320 ip 000000000041efab
sp 00000000ffa65038 error 6 in perf_fuzzer[400000+d1000]
[29396.986242] perf_fuzzer[7120]: segfault at 10e0 ip 000000000041efab
sp 00000000ffd48e68 error 6 in perf_fuzzer[400000+d1000]
[29738.892931] perf_fuzzer[7128]: segfault at 18c0 ip 000000000041efab
sp 00000000ffcdcd88 error 6 in perf_fuzzer[400000+d1000]
[29815.550210] perf_fuzzer[7132]: segfault at 120 ip 000000000041efab
sp 00000000ffe673b8 error 6 in perf_fuzzer[400000+d1000]
[30173.455348] perf_fuzzer[7141]: segfault at 120 ip 000000000041efab
sp 00000000ffda1948 error 6 in perf_fuzzer[400000+d1000]
[30570.625642] perf_fuzzer[7156]: segfault at 1680 ip 000000000041efab
sp 00000000ffaad028 error 6 in perf_fuzzer[400000+d1000]
[31047.887784] perf_fuzzer[7169]: segfault at 60c0 ip 000000000041efab
sp 00000000ffaa86e8 error 6 in perf_fuzzer[400000+d1000]
[31300.168714] perf_fuzzer[7175]: segfault at 3a80 ip 000000000041efab
sp 00000000ffd83228 error 6 in perf_fuzzer[400000+d1000]
[31984.727278] perf_fuzzer[7193]: segfault at 7e0 ip 000000000041efab

sp 00000000ff9db1f8 error 6 in perf_fuzzer[400000+d1000]

Vince

So I changed the perf_fuzzer so when it randomly stomps all over the perf_event_mmap_page, it uses a constant value of 0xdeadbeef rather than a random value.

The result is below. The segfaults make a bit more sense now, it almost looks like what is happening is we are corrupting an address value somehow (head? tail?) and the kernel then uses the corrupt address and writes to memory outside of the mmap ring buffer.

I still haven't figured out how to trigger this exactly, but you can see when over-written with 0xdeadbeef the memory address written to is consistently some small multiple of 0x120.

I imagine it would be a bad thing if it turned out to be possible to select what memory address got written to. Although since I've only reproduced this on x32 maybe it won't be possible to over-write the kernel; but I have seen this bug cause a reboot when the wrong thing got over-written.

[28002.850192] perf_fuzzer[7083]: segfault at 2be0 ip 000000000041efab sp 00000000ff826748 error 6 in perf_fuzzer[400000+d1000]
[28639.769869] perf_fuzzer[7100]: segfault at 1320 ip 000000000041efab sp 00000000ffa65038 error 6 in perf_fuzzer[400000+d1000]
[29396.986242] perf_fuzzer[7120]: segfault at 10e0 ip 000000000041efab sp 00000000ffd48e68 error 6 in perf_fuzzer[400000+d1000]
[29738.892931] perf_fuzzer[7128]: segfault at 18c0 ip 000000000041efab sp 00000000ffcdcd88 error 6 in perf_fuzzer[400000+d1000]
[29815.550210] perf_fuzzer[7132]: segfault at 120 ip 000000000041efab sp 00000000ffe673b8 error 6 in perf_fuzzer[400000+d1000]
[30173.455348] perf_fuzzer[7141]: segfault at 120 ip 000000000041efab sp 00000000ffda1948 error 6 in perf_fuzzer[400000+d1000]
[30570.625642] perf_fuzzer[7156]: segfault at 1680 ip 000000000041efab sp 00000000ffaad028 error 6 in perf_fuzzer[400000+d1000]
[31047.887784] perf_fuzzer[7169]: segfault at 60c0 ip 000000000041efab sp 00000000ffaa86e8 error 6 in perf_fuzzer[400000+d1000]
[31300.168714] perf_fuzzer[7175]: segfault at 3a80 ip 000000000041efab sp 00000000ffd83228 error 6 in perf_fuzzer[400000+d1000]
[31984.727278] perf_fuzzer[7193]: segfault at 7e0 ip 000000000041efab sp 00000000ff9db1f8 error 6 in perf_fuzzer[400000+d1000]

Error 6 reflects a write in userspace to a not-present page.

Since your previous trace indicates that the value of the register in question is a different one, I'm guessing that what we have here is PEBS getting activated. 0x120 is 2*0x90, and 0x90 is the size of a 64-bit PEBS record.

Quoted 3 lines · H. Peter Anvin

Error 6 reflects a write in userspace to a not-present page.

Since your previous trace indicates that the value of the register in

question

Quoted 1 line

is a different one, I'm guessing that what we have here is PEBS

getting

Quoted 1 line

activated. 0x120 is 2*0x90, and 0x90 is the size of a 64-bit PEBS

record.

I'm having problems generating a replayable syscall trace that exhibits

the problem.

It turns out that the segfault address listed (the multiple of 0x120) happens to be the value in the RBP register at the time of the segfault.

That's odd, as the instruction is

	movdqa %xmm0,(%rdi)
and rdi is the valid mmap address of the perf ring buffer
	rdi            0xf7768000	4151738368

so I'm not sure why RBP is involved at all.

In all of the cases I've investigated the precise_ip value has been set

for the problem event... but none of the events have been hardware events
(software and breakpoint so far). So probably not PEBS related?

Vince

Quoted 3 lines · H. Peter Anvin

Error 6 reflects a write in userspace to a not-present page.

Since your previous trace indicates that the value of the register in

question

Quoted 1 line

is a different one, I'm guessing that what we have here is PEBS

getting

Quoted 1 line

activated. 0x120 is 2*0x90, and 0x90 is the size of a 64-bit PEBS

record.

I'm having problems generating a replayable syscall trace that exhibits

the problem.

It turns out that the segfault address listed (the multiple of 0x120) happens to be the value in the RBP register at the time of the segfault.

That's odd, as the instruction is

	movdqa %xmm0,(%rdi)
and rdi is the valid mmap address of the perf ring buffer
	rdi            0xf7768000	4151738368

so I'm not sure why RBP is involved at all.

In all of the cases I've investigated the precise_ip value has been set

for the problem event... but none of the events have been hardware events
(software and breakpoint so far). So probably not PEBS related?

Vince

I'd be interested in how rbp gets set, too. It might just be a coincidence and the value in rbp has some other meaning here.

and as far as I can tell nothing touches rbp again until the segfault. Nothing in _memset_sse2 does as far as I can tell.

Quoted 3 lines · Vince Weaver

and as far as I can tell nothing touches rbp again until the segfault. Nothing in _memset_sse2 does as far as I can tell.

I only know enough about ftrace to be dangerous, but here is what I think is the trace of the problem:

     perf_fuzzer-11492 [000] 197077.488420: function:                perf_output_put_handle
     perf_fuzzer-11492 [000] 197077.488421: function:             __do_page_fault

So we do a write to the buffer rather immediately before this happens, and in particular that will update the head:

	rb->user_page->data_head = head;

However, that doesn't explain what is going on and in particular the write to whatever address was in %rbp. The rest pretty much seems to be the page fault logic.

Incidentally, I doubt that this is x32-related in any way; there seems to be absolutely no difference between x86-64 perf and x32 perf; more likely it just makes the error more reproducible because the address space is so much smaller.

Just touching the mmap page with a write of a single byte (it doesn't matter where) is enough to trigger the bug.

Quoted 3 lines · Vince Weaver

Just touching the mmap page with a write of a single byte (it doesn't

matter where) is enough to trigger the bug.

OK, investigating this more.

perf_fuzzer-2971 [000] 154.944114: page_fault_user:
address=0xf7729000 ip=0x41efab error_code=0x6
perf_fuzzer-2971 [000] 154.944118: function:
ip=0xffffffff810d40e7 parent_ip=0xffffffff810d0840
perf_fuzzer-2971 [000] 154.944119: function:
ip=0xffffffff812a91a5 parent_ip=0xffffffff81013ff5
perf_fuzzer-2971 [000] 154.944120: function:
ip=0xffffffff8153837c parent_ip=0xffffffff81535432
perf_fuzzer-2971 [000] 154.944121: page_fault_kernel:
address=0x22e0 ip=0xffffffff812a7d5c error_code=0x0

It looks like there are two page faults. The first is caused by the user
code accessing the mmap'd page. It looks sort of normal and what you'd expect if the perf_event mmap ring buffer is being accessed for the first
time.

What follows is a kernel page fault, and this is the one where for whatever reason CR2 has obtained the value of the userspace RBP register.

Vince

Quoted 8 lines · Vince Weaver

Quoted 3 lines · Vince Weaver

Just touching the mmap page with a write of a single byte (it doesn't

matter where) is enough to trigger the bug.

OK, investigating this more.

Quoted 10 lines

perf_fuzzer-2971 [000] 154.944114: page_fault_user:
address=0xf7729000 ip=0x41efab error_code=0x6
perf_fuzzer-2971 [000] 154.944118: function:
ip=0xffffffff810d40e7 parent_ip=0xffffffff810d0840
perf_fuzzer-2971 [000] 154.944119: function:
ip=0xffffffff812a91a5 parent_ip=0xffffffff81013ff5
perf_fuzzer-2971 [000] 154.944120: function:
ip=0xffffffff8153837c parent_ip=0xffffffff81535432
perf_fuzzer-2971 [000] 154.944121: page_fault_kernel:
address=0x22e0 ip=0xffffffff812a7d5c error_code=0x0

Ok, so the obvious question is what is at that kernel address?

Quoted 20 lines · H. Peter Anvin

Quoted 8 lines · Vince Weaver

Quoted 3 lines · Vince Weaver

Just touching the mmap page with a write of a single byte (it doesn't

matter where) is enough to trigger the bug.

OK, investigating this more.

Quoted 10 lines

perf_fuzzer-2971 [000] 154.944114: page_fault_user:
address=0xf7729000 ip=0x41efab error_code=0x6
perf_fuzzer-2971 [000] 154.944118: function:
ip=0xffffffff810d40e7 parent_ip=0xffffffff810d0840
perf_fuzzer-2971 [000] 154.944119: function:
ip=0xffffffff812a91a5 parent_ip=0xffffffff81013ff5
perf_fuzzer-2971 [000] 154.944120: function:
ip=0xffffffff8153837c parent_ip=0xffffffff81535432
perf_fuzzer-2971 [000] 154.944121: page_fault_kernel:
address=0x22e0 ip=0xffffffff812a7d5c error_code=0x0

Quoted 2 lines

Ok, so the obvious question is what is at that kernel address?

It's in copy_user_generic_string()

	rep movsq %ds:(%rsi),%es:(%rdi)

And looking at the ftrace:

     perf_fuzzer-2979  [000]   161.475920: page_fault_user:      address=__per_cpu_end ip=__per_cpu_end error_code=0x6
     perf_fuzzer-2979  [000]   161.475922: function:             perf_callchain
     perf_fuzzer-2979  [000]   161.475922: function:             copy_from_user_nmi
     perf_fuzzer-2979  [000]   161.475923: function:             trace_do_page_fault
     perf_fuzzer-2979  [000]   161.475924: page_fault_kernel:    address=irq_stack_union ip=copy_user_generic_string error_code=0x0

What is likely happening is the user page fault is triggering code to do a "perf_callchain" dump, which is calling copy_from_user_nmi() which calls copy_user_generic_string() which is somehow getting the user RBP in the RDI register somehow?

Quoted 35 lines · Vince Weaver

Quoted 20 lines · H. Peter Anvin

Quoted 8 lines · Vince Weaver

Quoted 3 lines · Vince Weaver

Just touching the mmap page with a write of a single byte (it doesn't

matter where) is enough to trigger the bug.

OK, investigating this more.

Quoted 10 lines

perf_fuzzer-2971 [000] 154.944114: page_fault_user:
address=0xf7729000 ip=0x41efab error_code=0x6
perf_fuzzer-2971 [000] 154.944118: function:
ip=0xffffffff810d40e7 parent_ip=0xffffffff810d0840
perf_fuzzer-2971 [000] 154.944119: function:
ip=0xffffffff812a91a5 parent_ip=0xffffffff81013ff5
perf_fuzzer-2971 [000] 154.944120: function:
ip=0xffffffff8153837c parent_ip=0xffffffff81535432
perf_fuzzer-2971 [000] 154.944121: page_fault_kernel:
address=0x22e0 ip=0xffffffff812a7d5c error_code=0x0

Quoted 2 lines

Ok, so the obvious question is what is at that kernel address?

It's in copy_user_generic_string()

	rep movsq %ds:(%rsi),%es:(%rdi)

And looking at the ftrace:

     perf_fuzzer-2979  [000]   161.475920: page_fault_user:      address=__per_cpu_end ip=__per_cpu_end error_code=0x6
     perf_fuzzer-2979  [000]   161.475922: function:             perf_callchain
     perf_fuzzer-2979  [000]   161.475922: function:             copy_from_user_nmi
     perf_fuzzer-2979  [000]   161.475923: function:             trace_do_page_fault
     perf_fuzzer-2979  [000]   161.475924: page_fault_kernel:    address=irq_stack_union ip=copy_user_generic_string error_code=0x0

Quoted 4 lines

What is likely happening is the user page fault is triggering code to do a "perf_callchain" dump, which is calling copy_from_user_nmi() which calls copy_user_generic_string() which is somehow getting the user RBP in the RDI register somehow?

So that code very much relies on the 'recursive' NMI/iret magic from Steve, patch 3f3c8b8c4b2a3 (and assorted fixes later).

If CR2 is getting corrupted; 7fbb98c5cb075 seems relevant.

Peter, does x32 have a slightly different ABI/calling convention that would make any of these patches just slightly 'off'?

I do note that

	perf_callchain_user();

Does

	fp = (void __user *)regs->bp;
	
	...

	bytes = copy_from_user_nmi(&frame, fp, sizeof(frame));

And in my particular executable RBP has nothing to do with a frame pointer, but is instead being used as a general purpose register.

Quoted 11 lines · Vince Weaver

I do note that

	perf_callchain_user();

Does

	fp = (void __user *)regs->bp;
	
	...

	bytes = copy_from_user_nmi(&frame, fp, sizeof(frame));

Quoted 2 lines

And in my particular executable RBP has nothing to do with a frame pointer, but is instead being used as a general purpose register.

and as a reminder, I'm seeing this on an x32 executable, so perf_callchain_user32() is probably coming into play.

So maybe it is an x32 issue after all.

I do note that

	perf_callchain_user();

Does

	fp = (void __user *)regs->bp;
	
	...

	bytes = copy_from_user_nmi(&frame, fp, sizeof(frame));

And in my particular executable RBP has nothing to do with a frame pointer, but is instead being used as a general purpose register.

Am I missing something here? Though in that case I'm not sure why this wouldn't be easier to trigger.

Quoted 3 lines

Peter, does x32 have a slightly different ABI/calling convention that would make any of these patches just slightly 'off'?

I do note that

	perf_callchain_user();

Does

	fp = (void __user *)regs->bp;
	
	...

	bytes = copy_from_user_nmi(&frame, fp, sizeof(frame));

And in my particular executable RBP has nothing to do with a frame pointer, but is instead being used as a general purpose register.

Am I missing something here? Though in that case I'm not sure why this wouldn't be easier to trigger.

Quoted 15 lines · Vince Weaver

Quoted 3 lines

Peter, does x32 have a slightly different ABI/calling convention that would make any of these patches just slightly 'off'?

I do note that

	perf_callchain_user();

Does

	fp = (void __user *)regs->bp;
	
	...

	bytes = copy_from_user_nmi(&frame, fp, sizeof(frame));

Quoted 6 lines

And in my particular executable RBP has nothing to do with a frame pointer, but is instead being used as a general purpose register.

Am I missing something here? Though in that case I'm not sure why this wouldn't be easier to trigger.

Neither x86-64 nor x32 are typically compiled with fixed frame pointers (which would be %rbp if they are). So I'm guessing the perf_callchain logic is only applicable to a user-space binary explicitly compiled with frame pointers turned on.

So copy_from_user_nmi() stumbles onto a nonexistent page and takes a page fault. This isn't a big deal, because perf_callchain_user() is set up to handle that (and just terminates the trace), *except* now CR2 is corrupt, and we took this event while handling a page fault already... and apparently before we even did read_cr2() in __do_page_fault.

The description of copy_from_user_nmi() states:

/*
* We rely on the nested NMI work to allow atomic faults from the NMI
path; the
* nested NMI paths are careful to preserve CR2.
*/

... but that doesn't seem to happen here for whatever reason.

There is no hint in your trace what happens after the kernel page fault so that makes it hard to know.

Quoted 44 lines · H. Peter Anvin

Quoted 15 lines · Vince Weaver

Quoted 3 lines

Peter, does x32 have a slightly different ABI/calling convention that would make any of these patches just slightly 'off'?

I do note that

	perf_callchain_user();

Does

	fp = (void __user *)regs->bp;
	
	...

	bytes = copy_from_user_nmi(&frame, fp, sizeof(frame));

Quoted 6 lines

And in my particular executable RBP has nothing to do with a frame pointer, but is instead being used as a general purpose register.

Am I missing something here? Though in that case I'm not sure why this wouldn't be easier to trigger.

Neither x86-64 nor x32 are typically compiled with fixed frame pointers (which would be %rbp if they are). So I'm guessing the perf_callchain logic is only applicable to a user-space binary explicitly compiled with frame pointers turned on.

So copy_from_user_nmi() stumbles onto a nonexistent page and takes a page fault. This isn't a big deal, because perf_callchain_user() is set up to handle that (and just terminates the trace), *except* now CR2 is corrupt, and we took this event while handling a page fault already... and apparently before we even did read_cr2() in __do_page_fault.

The description of copy_from_user_nmi() states:

/*
* We rely on the nested NMI work to allow atomic faults from the NMI
path; the
* nested NMI paths are careful to preserve CR2.
*/

... but that doesn't seem to happen here for whatever reason.

Quoted 2 lines

There is no hint in your trace what happens after the kernel page fault so that makes it hard to know.

Ahh, ftrace, the cause of and solution to all my perf_fuzzing problems.

Anyway I've attached the full tail end of the trace if you want to see everything that happens.

Quoted 3 lines

Anyway I've attached the full tail end of the trace if you want to see everything that happens.

and then I note there are *two* kernel page faults.

     perf_fuzzer-2979  [000]   161.475924: page_fault_kernel:    address=irq_stack_union ip=copy_user_generic_string error_code=0x0
address=0x1 ip=0xffffffff812a7d9c error_code=0x0
     perf_fuzzer-2979  [000]   161.475924: function:                __do_page_fault
     perf_fuzzer-2979  [000]   161.475924: function:                   bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475925: function:                      __bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475925: function:                         no_context
     perf_fuzzer-2979  [000]   161.475925: function:                            fixup_exception
     perf_fuzzer-2979  [000]   161.475926: function:                               search_exception_tables
     perf_fuzzer-2979  [000]   161.475926: function:                                  search_extable
     perf_fuzzer-2979  [000]   161.475927: function:             copy_user_handle_tail
     perf_fuzzer-2979  [000]   161.475927: function:             trace_do_page_fault
     perf_fuzzer-2979  [000]   161.475928: page_fault_kernel:    address=irq_stack_union ip=copy_user_handle_tail error_code=0x0
address=0x1 ip=0xffffffff812a92bb error_code=0x0
     perf_fuzzer-2979  [000]   161.475928: function:                __do_page_fault
     perf_fuzzer-2979  [000]   161.475928: function:                   bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475929: function:                      __bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475929: function:                         no_context
     perf_fuzzer-2979  [000]   161.475929: function:                            fixup_exception
     perf_fuzzer-2979  [000]   161.475929: function:                               search_exception_tables
     perf_fuzzer-2979  [000]   161.475930: function:                                  search_extable
     perf_fuzzer-2979  [000]   161.475931: function:             perf_output_begin
     perf_fuzzer-2979  [000]   161.475931: function:             perf_output_copy

That second one is in copy_user_handle_tail()

Quoted 29 lines · Vince Weaver

Quoted 3 lines

Anyway I've attached the full tail end of the trace if you want to see everything that happens.

and then I note there are *two* kernel page faults.

     perf_fuzzer-2979  [000]   161.475924: page_fault_kernel:    address=irq_stack_union ip=copy_user_generic_string error_code=0x0
address=0x1 ip=0xffffffff812a7d9c error_code=0x0
     perf_fuzzer-2979  [000]   161.475924: function:                __do_page_fault
     perf_fuzzer-2979  [000]   161.475924: function:                   bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475925: function:                      __bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475925: function:                         no_context
     perf_fuzzer-2979  [000]   161.475925: function:                            fixup_exception
     perf_fuzzer-2979  [000]   161.475926: function:                               search_exception_tables
     perf_fuzzer-2979  [000]   161.475926: function:                                  search_extable
     perf_fuzzer-2979  [000]   161.475927: function:             copy_user_handle_tail
     perf_fuzzer-2979  [000]   161.475927: function:             trace_do_page_fault
     perf_fuzzer-2979  [000]   161.475928: page_fault_kernel:    address=irq_stack_union ip=copy_user_handle_tail error_code=0x0
address=0x1 ip=0xffffffff812a92bb error_code=0x0
     perf_fuzzer-2979  [000]   161.475928: function:                __do_page_fault
     perf_fuzzer-2979  [000]   161.475928: function:                   bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475929: function:                      __bad_area_nosemaphore
     perf_fuzzer-2979  [000]   161.475929: function:                         no_context
     perf_fuzzer-2979  [000]   161.475929: function:                            fixup_exception
     perf_fuzzer-2979  [000]   161.475929: function:                               search_exception_tables
     perf_fuzzer-2979  [000]   161.475930: function:                                  search_extable
     perf_fuzzer-2979  [000]   161.475931: function:             perf_output_begin
     perf_fuzzer-2979  [000]   161.475931: function:             perf_output_copy

Quoted 2 lines

That second one is in copy_user_handle_tail()

Either way, it really seems like we have a case of CR2 leakage out of the NMI context.

Quoted 3 lines

Either way, it really seems like we have a case of CR2 leakage out of the NMI context.

Ah, and x86_64 saves off the cr2 register when entering NMI and restores it before returning. But it seems to be missing from the i386 code.

Ah, and x86_64 saves off the cr2 register when entering NMI and restores it before returning. But it seems to be missing from the i386 code.

Quoted 2 lines · Steven Rostedt

Ah, and x86_64 saves off the cr2 register when entering NMI and restores it before returning. But it seems to be missing from the i386 code.

arch/x86/kernel/nmi.c:

#define nmi_nesting_preprocess(regs)					\
	do {								\
		if (this_cpu_read(nmi_state) != NMI_NOT_RUNNING) {	\
			this_cpu_write(nmi_state, NMI_LATCHED);		\
			return;						\
		}							\
		this_cpu_write(nmi_state, NMI_EXECUTING);		\
		this_cpu_write(nmi_cr2, read_cr2());			\
	} while (0);							\
	nmi_restart:

#define nmi_nesting_postprocess()					\
	do {								\
		if (unlikely(this_cpu_read(nmi_cr2) != read_cr2()))	\
			write_cr2(this_cpu_read(nmi_cr2));		\
		if (this_cpu_dec_return(nmi_state))			\
			goto nmi_restart;				\
	} while (0)

That very much looks like saving/restoring CR2 to me.

FWIW; I hate how the x86_64 and i386 versions of this NMI nesting magic are so completely different.

Quoted 2 lines · Steven Rostedt

Ah, and x86_64 saves off the cr2 register when entering NMI and restores it before returning. But it seems to be missing from the i386 code.

arch/x86/kernel/nmi.c:

#define nmi_nesting_preprocess(regs)					\
	do {								\
		if (this_cpu_read(nmi_state) != NMI_NOT_RUNNING) {	\
			this_cpu_write(nmi_state, NMI_LATCHED);		\
			return;						\
		}							\
		this_cpu_write(nmi_state, NMI_EXECUTING);		\
		this_cpu_write(nmi_cr2, read_cr2());			\
	} while (0);							\
	nmi_restart:

#define nmi_nesting_postprocess()					\
	do {								\
		if (unlikely(this_cpu_read(nmi_cr2) != read_cr2()))	\
			write_cr2(this_cpu_read(nmi_cr2));		\
		if (this_cpu_dec_return(nmi_state))			\
			goto nmi_restart;				\
	} while (0)

That very much looks like saving/restoring CR2 to me.

FWIW; I hate how the x86_64 and i386 versions of this NMI nesting magic are so completely different.

Quoted 25 lines · Peter Zijlstra

Quoted 2 lines · Steven Rostedt

Ah, and x86_64 saves off the cr2 register when entering NMI and restores it before returning. But it seems to be missing from the i386 code.

arch/x86/kernel/nmi.c:

#define nmi_nesting_preprocess(regs)					\
	do {								\
		if (this_cpu_read(nmi_state) != NMI_NOT_RUNNING) {	\
			this_cpu_write(nmi_state, NMI_LATCHED);		\
			return;						\
		}							\
		this_cpu_write(nmi_state, NMI_EXECUTING);		\
		this_cpu_write(nmi_cr2, read_cr2());			\
	} while (0);							\
	nmi_restart:

#define nmi_nesting_postprocess()					\
	do {								\
		if (unlikely(this_cpu_read(nmi_cr2) != read_cr2()))	\
			write_cr2(this_cpu_read(nmi_cr2));		\
		if (this_cpu_dec_return(nmi_state))			\
			goto nmi_restart;				\
	} while (0)

Quoted 4 lines

That very much looks like saving/restoring CR2 to me.

FWIW; I hate how the x86_64 and i386 versions of this NMI nesting magic are so completely different.

Is there any way that nmi_cr2 can end up getting overwritten by multiple nestings of some kind? I would have thought it would have made more sense to spill cr2 onto the stack after the stack has been properly set up.

Quoted 3 lines · H. Peter Anvin

Quoted 2 lines · Peter Zijlstra

Quoted 1 line · Steven Rostedt

Ah, and x86_64 saves off the cr2 register when entering NMI and

restores

Quoted 1 line

Quoted 1 line

Quoted 1 line

it before returning. But it seems to be missing from the i386

code.

Quoted 22 lines

Quoted 22 lines

arch/x86/kernel/nmi.c:

#define nmi_nesting_preprocess(regs)					\
	do {								\
		if (this_cpu_read(nmi_state) != NMI_NOT_RUNNING) {	\
			this_cpu_write(nmi_state, NMI_LATCHED);		\
			return;						\
		}							\
		this_cpu_write(nmi_state, NMI_EXECUTING);		\
		this_cpu_write(nmi_cr2, read_cr2());			\
	} while (0);							\
	nmi_restart:

#define nmi_nesting_postprocess()					\
	do {								\
		if (unlikely(this_cpu_read(nmi_cr2) != read_cr2()))	\
			write_cr2(this_cpu_read(nmi_cr2));		\
		if (this_cpu_dec_return(nmi_state))			\
			goto nmi_restart;				\
	} while (0)

Quoted 3 lines

Quoted 3 lines

That very much looks like saving/restoring CR2 to me.

FWIW; I hate how the x86_64 and i386 versions of this NMI nesting

magic

Quoted 3 lines

Quoted 1 line

are so completely different.

Is there any way that nmi_cr2 can end up getting overwritten by

multiple

Quoted 2 lines

nestings of some kind? I would have thought it would have made more sense to spill cr2 onto the stack after the stack has been properly

set up.

So how can I help with debugging this?

While the missing cr2 issue made debugging frustrating, I find the other
aspects of the bug more serious:

1. Programs that are doing valid memory accesses can segfault
and worse
2. This bug can cause an instant-reboot of the system (I assume somehow
with the right combination of memory accesses it causes a triple-fault?)

#2 is why I spent all of this time tracking this down, I couldn't leave a
machine fuzzing overnight without the machine rebooting.

Vince

#2 is what I really don't understand.

I worry something else is going on there

Quoted 18 lines

While the missing cr2 issue made debugging frustrating, I find the other
aspects of the bug more serious:

1. Programs that are doing valid memory accesses can segfault
and worse
2. This bug can cause an instant-reboot of the system (I assume somehow
with the right combination of memory accesses it causes a triple-fault?)

#2 is why I spent all of this time tracking this down, I couldn't leave a
machine fuzzing overnight without the machine rebooting.

Vince

Quoted 3 lines · On Tue, 25 Feb 2014 06:34:55 -0800 "H. Peter Anvin" <[email protected]> wrote:

#2 is what I really don't understand.

I worry something else is going on there

Yeah, me too.

Quoted 5 lines · Steven Rostedt

Quoted 2 lines · On Tue, 25 Feb 2014 06:34:55 -0800 "H. Peter Anvin" <[email protected]> wrote:

#2 is what I really don't understand.

Quoted 4 lines

Quoted 1 line

I worry something else is going on there

Yeah, me too.

OK, well I'll work on isolating that next, I was hoping the segfault issue was related. It's a lot harder getting traces out of a machine that insta-reboots so fast that it can't even finish printing the oops message.

I spent some more time on this.
I managed to get a trace that exhibited the bug practically right away, but still unable to generate a reproducible trace :(

So instead I'm adding WARN's and trace_printks to see what I can find out.

Here's a summary of what I think is happneing. Please let me know if I'm wildly wrong in analyzing this.

Userspace accesses the perf
ring-buffer-user-page of an event for the first time (in this trace it's a SW_CPU_CLOCK event).

This triggers a page_fault to bring in the page.

This triggers a TRACEPOINT event (task/task_newtask) which
has PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_CALLCHAIN|PERF_SAMPLE_ID|PERF_SAMPLE_CPU|PERF_SAMPLE_PERIOD|PERF_SAMPLE_STREAM_ID|PERF_SAMPLE_WEIGHT|PERF_SAMPLE_DATA_SRC|PERF_SAMPLE_TRANSACTION; and exclude_callchain_kernel=1, triggering a perf_callchain().

Here is a dump of the stack right after we enter perf_callchain()

vince@core2:~$ [  202.320444] ------------[ cut here ]------------
[  202.324001] WARNING: CPU: 1 PID: 2873 at kernel/events/callchain.c:168 perf_callchain+0x67/0x211()
hermal_sys ehci_pci ehci_hcd sg sd_mod usbcore usb_common
[  202.324001] CPU: 1 PID: 2873 Comm: perf_fuzzer Not tainted 3.14.0-rc3+ #24
[  202.324001] Hardware name: AOpen   DE7000/nMCP7ALPx-DE R1.06 Oct.19.2012, BIOS 080015  10/19/2012
[  202.324001]  00000000000000a8 ffff880119ec1b48 ffffffff81531dc1 00000000000000a8
[  202.324001]  0000000000000000 ffff880119ec1b88 ffffffff81040ce4 ffff880119ec1b88
[  202.324001]  ffffffff810d416f ffff880119ec1e38 ffff8800cba67800 0000000000000000
[  202.324001] Call Trace:
[  202.324001]  [<ffffffff81531dc1>] dump_stack+0x49/0x60
[  202.324001]  [<ffffffff81040ce4>] warn_slowpath_common+0x81/0x9b
[  202.324001]  [<ffffffff810d416f>] ? perf_callchain+0x67/0x211
[  202.324001]  [<ffffffff81040d18>] warn_slowpath_null+0x1a/0x1c
[  202.324001]  [<ffffffff810d416f>] perf_callchain+0x67/0x211
[  202.324001]  [<ffffffff8106b0ab>] ? local_clock+0x1b/0x24
[  202.324001]  [<ffffffff810d0872>] perf_prepare_sample+0x7b/0x304
[  202.324001]  [<ffffffff810d1079>] __perf_event_overflow+0x156/0x1c1
[  202.324001]  [<ffffffff810f4613>] ? free_pgtables+0xa7/0xc9
[  202.324001]  [<ffffffff810d125e>] perf_swevent_overflow+0x41/0x5b
[  202.324001]  [<ffffffff810d12ea>] perf_swevent_event+0x72/0x74
[  202.324001]  [<ffffffff810d1478>] perf_tp_event+0xea/0x1ef
[  202.324001]  [<ffffffff8103515a>] ? perf_trace_x86_exceptions+0x4c/0xba
[  202.324001]  [<ffffffff810351b6>] perf_trace_x86_exceptions+0xa8/0xba
[  202.324001]  [<ffffffff8103515a>] ? perf_trace_x86_exceptions+0x4c/0xba
[  202.324001]  [<ffffffff81538439>] trace_do_page_fault+0x48/0x99
[  202.324001]  [<ffffffff815354b2>] trace_page_fault+0x22/0x30
[  202.324001] ---[ end trace 31ccd31b4e82cb42 ]---

This triggers a kernel pagefault because the BP register is not valid and copy_from_user_nmi() tries to copy the user stack area from there.

This *should* be OK? And it maybe looks like it works, but then

copy_user_handle_tail()

causes another page fault again at the invaid BP register.

But then the code continues to
perf_output_begin()

237.265689: page_fault_kernel: address=0x17a0 ip=copy_user_handle_tail error_code=0x0
237.265689: function: __do_page_fault
237.265689: function: bad_area_nosemaphore
237.265690: function: __bad_area_nosemaphore
237.265690: function: no_context
237.265690: function: fixup_exception
237.265690: function: search_exception_tables
237.265690: function: search_extable
237.265691: function: perf_output_begin

237.265692: bprint: perf_output_begin: VMW: event type 2 config 2a st: 2c3e7

how are we back in __do_page_fault again here?

237.265692: function: __do_page_fault

237.265692: function:                down_read_trylock
237.265692: function:                _cond_resched
237.265693: function:                find_vma
237.265693: function:                bad_area

237.265693: function: up_read
237.265693: function: __bad_area_nosemaphore
237.265694: function: is_prefetch
237.265694: function: convert_ip_to_linear
237.265695: function: unhandled_signal
237.265695: function: __printk_ratelimit
237.265695: function: _raw_spin_trylock
237.265695: function: _raw_spin_unlock_irqrestore
237.265696: function: printk
237.265696: function: vprintk_emit

[  202.877004] perf_fuzzer[2873]: segfault at 17a0 ip 00000000004017fd sp 00000000ffd19d10 error 6 in perf_fuzzer[400000+d1000]

Yeah, something is getting mesed up.

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2 save/restore, which doesn't nest because it is a percpu variable.

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

I would actually suggest we do the equivalent on i386 as well.

Vince, could you try this patch as an experiment?

Quoted 8 lines · On Thu, 27 Feb 2014 14:52:54 -0800 "H. Peter Anvin" <[email protected]> wrote:

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2 save/restore, which doesn't nest because it is a percpu variable.

Quoted 3 lines

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

Peter, look at the code. That percpu cr2 is in a #ifdef CONFIG_X86_32 section. That is, it isn't even executed. That's i386 code. The only place the cr2 is saved for x86_64 is in entry_64.S.

Quoted 11 lines · Steven Rostedt

Quoted 8 lines · On Thu, 27 Feb 2014 14:52:54 -0800 "H. Peter Anvin" <[email protected]> wrote:

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2 save/restore, which doesn't nest because it is a percpu variable.

Quoted 8 lines

Quoted 3 lines

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

Peter, look at the code. That percpu cr2 is in a #ifdef CONFIG_X86_32 section. That is, it isn't even executed. That's i386 code. The only place the cr2 is saved for x86_64 is in entry_64.S.

Right, egg on my face. However, I still think it would make more sense for it to nest the way entry_64.S does if at all possible.

That makes this even more confusing, though. I would still like to see what happens with the patch I sent Vince.

Quoted 21 lines · H. Peter Anvin

Quoted 11 lines · Steven Rostedt

Quoted 8 lines · On Thu, 27 Feb 2014 14:52:54 -0800 "H. Peter Anvin" <[email protected]> wrote:

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2 save/restore, which doesn't nest because it is a percpu variable.

Quoted 8 lines

Quoted 3 lines

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

Peter, look at the code. That percpu cr2 is in a #ifdef CONFIG_X86_32 section. That is, it isn't even executed. That's i386 code. The only place the cr2 is saved for x86_64 is in entry_64.S.

Quoted 5 lines

Right, egg on my face. However, I still think it would make more sense for it to nest the way entry_64.S does if at all possible.

That makes this even more confusing, though. I would still like to see what happens with the patch I sent Vince.

I'll try your patch momentarily, first I had some other changes I started running before I left work (for some reason it recompiled the whole kernel).

8: function:             perf_output_begin
8: bprint:               perf_output_begin: VMW: event type 2 config 2a st: 2c3e
8: bputs:                perf_output_begin: VMW: before rcu_dereference
9: function:             __do_page_fault
9: function:                down_read_trylock
9: function:                _cond_resched
9: function:                find_vma

so it looks like the fault happens

rcu_read_lock();

116 /*
117 * For inherited events we send all the output towards the parent.
118 */
119 if (event->parent)
120 event = event->parent;
121

somewhere between here

122 rb = rcu_dereference(event->rb);
123 if (unlikely(!rb))
124 goto out;

and here

125
126 if (unlikely(!rb->nr_pages))
127 goto out;

although if rcu locks do anything to turn off tracing then this could be suspect.

Quoted 64 lines · Vince Weaver

Quoted 21 lines · H. Peter Anvin

Quoted 11 lines · Steven Rostedt

Quoted 8 lines · On Thu, 27 Feb 2014 14:52:54 -0800 "H. Peter Anvin" <[email protected]> wrote:

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2 save/restore, which doesn't nest because it is a percpu variable.

Quoted 8 lines

Quoted 3 lines

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

Peter, look at the code. That percpu cr2 is in a #ifdef CONFIG_X86_32 section. That is, it isn't even executed. That's i386 code. The only place the cr2 is saved for x86_64 is in entry_64.S.

Quoted 5 lines

Right, egg on my face. However, I still think it would make more sense for it to nest the way entry_64.S does if at all possible.

That makes this even more confusing, though. I would still like to see what happens with the patch I sent Vince.

I'll try your patch momentarily, first I had some other changes I started running before I left work (for some reason it recompiled the whole kernel).

8: function:             perf_output_begin
8: bprint:               perf_output_begin: VMW: event type 2 config 2a st: 2c3e
8: bputs:                perf_output_begin: VMW: before rcu_dereference
9: function:             __do_page_fault
9: function:                down_read_trylock
9: function:                _cond_resched
9: function:                find_vma

so it looks like the fault happens

rcu_read_lock();

116 /*
117 * For inherited events we send all the output towards the parent.
118 */
119 if (event->parent)
120 event = event->parent;
121

somewhere between here

122 rb = rcu_dereference(event->rb);
123 if (unlikely(!rb))
124 goto out;

and here

125
126 if (unlikely(!rb->nr_pages))
127 goto out;

Quoted 2 lines

although if rcu locks do anything to turn off tracing then this could be suspect.

The most likely suspect is of course event->rb in the rcu_dereference. I have to defer to Steven on how rcu_read_lock() and rcu_read_unlock() currently interact with tracing. ;-)

Quoted 35 lines

Quoted 35 lines

I'll try your patch momentarily, first I had some other changes I started running before I left work (for some reason it recompiled the whole kernel).

8: function:             perf_output_begin
8: bprint:               perf_output_begin: VMW: event type 2 config 2a st: 2c3e
8: bputs:                perf_output_begin: VMW: before rcu_dereference
9: function:             __do_page_fault
9: function:                down_read_trylock
9: function:                _cond_resched
9: function:                find_vma

so it looks like the fault happens

rcu_read_lock();

116 /*
117 * For inherited events we send all the output towards the parent.
118 */
119 if (event->parent)
120 event = event->parent;
121

somewhere between here

122 rb = rcu_dereference(event->rb);
123 if (unlikely(!rb))
124 goto out;

and here

125
126 if (unlikely(!rb->nr_pages))
127 goto out;

Quoted 6 lines

Quoted 2 lines

although if rcu locks do anything to turn off tracing then this could be suspect.

The most likely suspect is of course event->rb in the rcu_dereference. I have to defer to Steven on how rcu_read_lock() and rcu_read_unlock() currently interact with tracing. ;-)

These are all perf related. You'll need to defer to Peter Zijlstra ;-)

Quoted 42 lines · Steven Rostedt

Quoted 41 lines

Quoted 29 lines

I'll try your patch momentarily, first I had some other changes I started running before I left work (for some reason it recompiled the whole kernel).

8: function:             perf_output_begin
8: bprint:               perf_output_begin: VMW: event type 2 config 2a st: 2c3e
8: bputs:                perf_output_begin: VMW: before rcu_dereference
9: function:             __do_page_fault
9: function:                down_read_trylock
9: function:                _cond_resched
9: function:                find_vma

so it looks like the fault happens

rcu_read_lock();

116 /*
117 * For inherited events we send all the output towards the parent.
118 */
119 if (event->parent)
120 event = event->parent;
121

somewhere between here

122 rb = rcu_dereference(event->rb);
123 if (unlikely(!rb))
124 goto out;

Quoted 8 lines

and here

125
126 if (unlikely(!rb->nr_pages))
127 goto out;

although if rcu locks do anything to turn off tracing then this could be suspect.

The most likely suspect is of course event->rb in the rcu_dereference. I have to defer to Steven on how rcu_read_lock() and rcu_read_unlock() currently interact with tracing. ;-)

Quoted 1 line

These are all perf related. You'll need to defer to Peter Zijlstra ;-)

I'm lost.. :/

pretty much all perf objects are RCU freed.

This code isn't running in idle context is it? If so, RCU will happily free out from under it. CONFIG_PROVE_RCU should detect this sort of thing, though.

Quoted 3 lines · Paul E. McKenney

This code isn't running in idle context is it? If so, RCU will happily free out from under it. CONFIG_PROVE_RCU should detect this sort of thing, though.

Well, interrupts/NMIs can happen when idle, but the interrupt/NMI entry code deals with the idle state AFAIK.

Quoted 5 lines · Peter Zijlstra

Quoted 3 lines · Paul E. McKenney

This code isn't running in idle context is it? If so, RCU will happily free out from under it. CONFIG_PROVE_RCU should detect this sort of thing, though.

Quoted 2 lines

Well, interrupts/NMIs can happen when idle, but the interrupt/NMI entry code deals with the idle state AFAIK.

Yep, rcu_irq_enter() and rcu_nmi_enter() deal with that. More worried about this being code invoked from some energy-efficiency driver or another within the idle loop.

Quoted 9 lines · Paul E. McKenney

Quoted 7 lines · Peter Zijlstra

Quoted 3 lines · Paul E. McKenney

This code isn't running in idle context is it? If so, RCU will happily free out from under it. CONFIG_PROVE_RCU should detect this sort of thing, though.

Well, interrupts/NMIs can happen when idle, but the interrupt/NMI entry code deals with the idle state AFAIK.

Quoted 3 lines

Yep, rcu_irq_enter() and rcu_nmi_enter() deal with that. More worried about this being code invoked from some energy-efficiency driver or another within the idle loop.

Right, so any tracepoint can end up there; but I thought there was already the rule that tracepoints needed RCU enabled.

Quoted 14 lines · On Fri, 28 Feb 2014 22:55:11 +0100 Peter Zijlstra <[email protected]> wrote:

Quoted 12 lines · Paul E. McKenney

Quoted 7 lines · Peter Zijlstra

Quoted 3 lines · Paul E. McKenney

This code isn't running in idle context is it? If so, RCU will happily free out from under it. CONFIG_PROVE_RCU should detect this sort of thing, though.

Well, interrupts/NMIs can happen when idle, but the interrupt/NMI entry code deals with the idle state AFAIK.

Yep, rcu_irq_enter() and rcu_nmi_enter() deal with that. More worried about this being code invoked from some energy-efficiency driver or another within the idle loop.

Quoted 2 lines

Right, so any tracepoint can end up there; but I thought there was already the rule that tracepoints needed RCU enabled.

There is and we have special tracepoint caller for those cases we want a tracepoint out of RCU scope. These will reactivate rcu in the tracepoint code.

trace_<tp_name>_rcuidle(...)

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2 save/restore, which doesn't nest because it is a percpu variable.

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

I would actually suggest we do the equivalent on i386 as well.

Vince, could you try this patch as an experiment?

Quoted 6 lines · H. Peter Anvin

Quoted 3 lines · Steven Rostedt

Yeah, something is getting mesed up.

What it *looks* like to me is that we try to nest the cr2

save/restore,

Quoted 9 lines

which doesn't nest because it is a percpu variable.

... except in the x86-64 case, we *ALSO* save/restore cr2 inside entry_64.S, which makes the stuff in do_nmi completely redundant and there for no good reason.

I would actually suggest we do the equivalent on i386 as well.

Vince, could you try this patch as an experiment?

OK with your patch applied it does not segfault.

The trace looks like you'd expect too:

perf_fuzzer-2910 [000] 255.355331: page_fault_kernel:
address=irq_stack_union ip=copy_user_handle_tail error_code=0x0
perf_fuzzer-2910 [000] 255.355331: function:
__do_page_fault
perf_fuzzer-2910 [000] 255.355331: function:
bad_area_nosemaphore
perf_fuzzer-2910 [000] 255.355331: function:
__bad_area_nosemaphore
perf_fuzzer-2910 [000] 255.355332: function:
no_context
perf_fuzzer-2910 [000] 255.355332: function:
fixup_exception
perf_fuzzer-2910 [000] 255.355332: function:
search_exception_tables
perf_fuzzer-2910 [000] 255.355332: function:
search_extable
perf_fuzzer-2910 [000] 255.355333: function:
perf_output_begin
perf_fuzzer-2910 [000] 255.355333: bprint:
perf_output_begin: VMW: event type 2 config 2a st: 2c3e7
perf_fuzzer-2910 [000] 255.355333: bprint:
perf_output_begin: VMW: before event->parent (nil)
perf_fuzzer-2910 [000] 255.355334: bprint:
perf_output_begin: VMW: before rcu_dereference (nil)
perf_fuzzer-2910 [000] 255.355334: function:
__do_page_fault
perf_fuzzer-2910 [000] 255.355334: function:
down_read_trylock
perf_fuzzer-2910 [000] 255.355334: function:
_cond_resched

perf_fuzzer-2910  [000]   255.355335: function:                find_vma
perf_fuzzer-2910  [000]   255.355335: function:               

handle_mm_fault
perf_fuzzer-2910 [000] 255.355335: function:
__do_fault
perf_fuzzer-2910 [000] 255.355335: bputs:
perf_mmap_fault: VMW: perf_mmap_fault
perf_fuzzer-2910 [000] 255.355336: bprint:
perf_mmap_fault: VMW: perf_mmap_fault 0xffff8800cba6a980
perf_fuzzer-2910 [000] 255.355336: function:
perf_mmap_to_page
perf_fuzzer-2910 [000] 255.355336: function:
_cond_resched
perf_fuzzer-2910 [000] 255.355336: function:
unlock_page
perf_fuzzer-2910 [000] 255.355336: function:
page_waitqueue
perf_fuzzer-2910 [000] 255.355337: function:
__wake_up_bit
perf_fuzzer-2910 [000] 255.355337: bputs:
perf_mmap_fault: VMW: perf_mmap_fault
perf_fuzzer-2910 [000] 255.355337: function:
_cond_resched
perf_fuzzer-2910 [000] 255.355337: function:
_raw_spin_lock
perf_fuzzer-2910 [000] 255.355337: function:
page_add_file_rmap
perf_fuzzer-2910 [000] 255.355338: function:
__inc_zone_page_state
perf_fuzzer-2910 [000] 255.355338: function:
__inc_zone_state
perf_fuzzer-2910 [000] 255.355338: function:
set_page_dirty
perf_fuzzer-2910 [000] 255.355338: function:
page_mapping
perf_fuzzer-2910 [000] 255.355338: function:
anon_set_page_dirty
perf_fuzzer-2910 [000] 255.355339: function:
unlock_page

Vince

Quoted 3 lines

I would actually suggest we do the equivalent on i386 as well.

Vince, could you try this patch as an experiment?

OK with your patch applied it does not segfault.

arch/x86/kernel/nmi.c +2 -0

@@ -512,8 +508,21 @@ static inline void nmi_nesting_postprocess(void)
 dotraplinkage notrace __kprobes void
 do_nmi(struct pt_regs *regs, long error_code)
 {
+	unsigned long cr2;
+	
 	nmi_nesting_preprocess(regs);

arch/x86/kernel/nmi.c +3 -0

+	 */
+	cr2 = read_cr2();
+
 	nmi_enter();
 

arch/x86/kernel/nmi.c +4 -0

 	inc_irq_stat(__nmi_count);

@@ -523,6 +532,10 @@ do_nmi(struct pt_regs *regs, long error_code)
 
 	nmi_exit();
 
+	/* Reads are cheaper than writes */
+	if (unlikely(cr2 != read_cr2()))
+		write_cr2(cr2);
+
 	/* On i386, may loop back to preprocess */
 	nmi_nesting_postprocess();
 }

Quoted 15 lines · Steven Rostedt

arch/x86/kernel/nmi.c +9 -0

@@ -512,8 +508,21 @@ static inline void nmi_nesting_postprocess(void)
 dotraplinkage notrace __kprobes void
 do_nmi(struct pt_regs *regs, long error_code)
 {
+	unsigned long cr2;
+	
 	nmi_nesting_preprocess(regs);
 
+	/*
+	 * Save off the CR2 register. If we take a page fault in the NMI then
+	 * it could corrupt the CR2 value. If the NMI preempts a page fault
+	 * handler before it was able to read the CR2 register, and then the
+	 * NMI itself takes a page fault, the page fault that was preempted
+	 * will read the information from the NMI page fault and not the
+	 * origin fault. Save it off and restore it if it changes.

arch/x86/kernel/nmi.c static inline void nmi_nesting_postprocess(void) · line 522

Quoted 1 line

arch/x86/kernel/nmi.c +1 -0

+	 * Use the r12 callee-saved register.

You might want to make that line go away :-)

Quoted 2 lines · On Thu, 27 Feb 2014 20:34:34 -0500 (EST) Vince Weaver…

Quoted 2 lines

I would actually suggest we do the equivalent on i386 as well.

Quoted 4 lines

Quoted 1 line

Vince, could you try this patch as an experiment?

OK with your patch applied it does not segfault.

Vince, Great! Can you remove Peter's patch, and try this one. It removes the crud to save the cr2 from entry_64.S and makes both i386 and x86_64 do the same thing in regards to cr2 handling.

Quoted 11 lines · Steven Rostedt

Quoted 6 lines · On Thu, 27 Feb 2014 20:34:34 -0500 (EST) Vince Weaver…

Quoted 3 lines

I would actually suggest we do the equivalent on i386 as well.

Vince, could you try this patch as an experiment?

OK with your patch applied it does not segfault.

Quoted 3 lines

Vince, Great! Can you remove Peter's patch, and try this one. It removes the crud to save the cr2 from entry_64.S and makes both i386 and x86_64 do the same thing in regards to cr2 handling.

no, with only this patch applied it segfaults as per previous:

[  126.396049] perf_fuzzer[2904]: segfault at 17a0 ip 00000000004017fd sp 00000000ffaff3f0 error 6 in perf_fuzzer[400000+d1000]

Interesting. Are you doing a perf function trace?

And just in case, can you add this patch and make sure the copy is called by NMI.

Quoted 4 lines · Steven Rostedt

Interesting. Are you doing a perf function trace?

And just in case, can you add this patch and make sure the copy is called by NMI.

199.900682: function: trace_do_page_fault
199.900683: page_fault_user: address=__per_cpu_end
ip=__per_cpu_end error_code=0x6
199.900683: function: perf_swevent_get_recursion_context
199.900684: function: perf_tp_event
199.900684: function: perf_swevent_event
199.900684: function: perf_swevent_overflow
199.900684: function: __perf_event_overflow
199.900685: function: perf_prepare_sample
199.900685: function:
__perf_event_header__init_id
199.900685: function: task_tgid_nr_ns
199.900685: function: perf_event_tid
199.900686: function: __task_pid_nr_ns
199.900686: function: perf_callchain

199.900687: function:             copy_from_user_nmi
199.900687: function:             trace_do_page_fault
199.900687: page_fault_kernel:    address=irq_stack_union

ip=copy_user_generic_string error_code=0x0
199.900688: function: __do_page_fault
199.900688: function: bad_area_nosemaphore
199.900688: function: __bad_area_nosemaphore
199.900689: function: no_context
199.900689: function: fixup_exception
199.900689: function:
search_exception_tables
199.900689: function: search_extable

199.900691: function:             copy_user_handle_tail
199.900691: function:             trace_do_page_fault
199.900691: page_fault_kernel:    address=irq_stack_union

ip=copy_user_handle_tail error_code=0x0
199.900691: function: __do_page_fault
199.900692: function: bad_area_nosemaphore
199.900692: function: __bad_area_nosemaphore
199.900692: function: no_context
199.900692: function: fixup_exception
199.900692: function:
search_exception_tables
199.900692: function: search_extable
199.900693: function: save_stack_trace
199.900693: function: dump_trace
199.900694: function: print_context_stack
199.900694: function: __kernel_text_address
199.900694: function: is_module_text_address
199.900695: function: __module_text_address
199.900695: function: __module_address
199.900695: function: __kernel_text_address
199.900695: function: is_module_text_address
199.900696: function: __module_text_address
199.900696: function: __module_address
...
199.900705: function: __kernel_text_address
199.900809: kernel_stack: <stack trace>
=> perf_callchain (ffffffff810d35a2)
=> perf_prepare_sample (ffffffff810cfae3)
=> __perf_event_overflow (ffffffff810d02f4)
=> perf_swevent_overflow (ffffffff810d04e3)
=> perf_swevent_event (ffffffff810d0574)
=> perf_tp_event (ffffffff810d070c)
=> perf_trace_x86_exceptions (ffffffff810341b6)
=> trace_do_page_fault (ffffffff81537702)
=> trace_page_fault (ffffffff81534772)
199.900810: function: perf_output_begin
199.900810: function: __do_page_fault
199.900810: function: __perf_sw_event
199.900810: function:
perf_swevent_get_recursion_context

199.900811: function:                down_read_trylock
199.900811: function:                _cond_resched
199.900811: function:                find_vma
199.900811: function:                bad_area

199.900812: function: up_read
199.900812: function: __bad_area_nosemaphore
199.900812: function: is_prefetch
199.900812: function: convert_ip_to_linear
199.900813: function: unhandled_signal
199.900813: function: __printk_ratelimit
199.900813: function: _raw_spin_trylock
199.900813: function: _raw_spin_unlock_irqrestore
199.900814: function: printk
199.900814: function: vprintk_emit

If I'm reading this right we end up going from the page fault tracepoint to copy_from_user_nmi() without going through NMI, and the cr2 corruption is obvious. I guess the assumption that only the NMI path needed to save cr2 is flawed?

Quoted 4 lines · H. Peter Anvin

If I'm reading this right we end up going from the page fault tracepoint to copy_from_user_nmi() without going through NMI, and the cr2 corruption is obvious. I guess the assumption that only the NMI path needed to save cr2 is flawed?

It was never assumed it would only go through NMI, but that it would be NMI safe -- and as it turns out, it is that.

What I did assume was that any other callsites would be safe, seeing how they'd already be running in 'normal' contexts.

I had not considered people putting tracepoints _that_ early in the exception paths.

Note that there's more tracepoints there than the one mentioned.

Well, I was talking about the assumption spelled out in the comment above copy_from_user_nmi() which pretty much states "cr2 is safe because cr2 is saved/restored in the NMI wrappers."

[ H. Peter, Here's the rename patch. I did not include your update. You can add that first and then massage this patch on top. But this isn't critical for mainline or stable, where as I believe your patch is. ]

The tracing utilities sometimes need to read from userspace (stack tracing), and to do this it has as special copy_from_user function called copy_from_user_nmi(). Well, as tracers can call this from outside of nmi context, the "_nmi" part is a misnomer and "_trace" is a better name.

Quoted 9 lines · Steven Rostedt

[ H. Peter, Here's the rename patch. I did not include your update. You can add that first and then massage this patch on top. But this isn't critical for mainline or stable, where as I believe your patch is. ]

The tracing utilities sometimes need to read from userspace (stack tracing), and to do this it has as special copy_from_user function called copy_from_user_nmi(). Well, as tracers can call this from outside of nmi context, the "_nmi" part is a misnomer and "_trace" is a better name.

NAK, spin_lock_irq() is very much an IRQ safe lock. Similarly copy_from_user_nmi() is an NMI safe copy from user.

Furthermore, there's exactly 0 trace users, so the proposed name is actively worse.

Quoted 11 lines · On Fri, 28 Feb 2014 21:46:21 +0100 Peter Zijlstra <[email protected]> wrote:

Quoted 9 lines · Steven Rostedt

[ H. Peter, Here's the rename patch. I did not include your update. You can add that first and then massage this patch on top. But this isn't critical for mainline or stable, where as I believe your patch is. ]

The tracing utilities sometimes need to read from userspace (stack tracing), and to do this it has as special copy_from_user function called copy_from_user_nmi(). Well, as tracers can call this from outside of nmi context, the "_nmi" part is a misnomer and "_trace" is a better name.

Quoted 5 lines

NAK, spin_lock_irq() is very much an IRQ safe lock. Similarly copy_from_user_nmi() is an NMI safe copy from user.

Furthermore, there's exactly 0 trace users, so the proposed name is actively worse.

Heh, I consider perf and oprofile special tracers ;-)

NAK, spin_lock_irq() is very much an IRQ safe lock. Similarly

copy_from_user_nmi() is an NMI safe copy from user.

Furthermore, there's exactly 0 trace users, so the proposed name is actively worse.

OK, I'll go with that. So instead of an _nmi() which it has nothing to do with NMIs,

how about making it like spin_lock_irq() and a more descriptive name about what it does?

copy_from_user_savecr2()

Quoted 3 lines · On Fri, 28 Feb 2014 08:15:11 -0800 "H. Peter Anvin" <[email protected]> wrote:

Well, I was talking about the assumption spelled out in the comment above copy_from_user_nmi() which pretty much states "cr2 is safe because cr2 is saved/restored in the NMI wrappers."

Yeah, it seems that the name "copy_from_user_nmi()" is a misnomer. As it can be called outside of nmi context. Perhaps we should have a copy_from_user_trace() that does the save and restore of the cr2.

As that's the only place that faults, it may be the best answer.

Arnaldo,

Can you test this patch and see if it fixes the bug for you too. Vince already said it fixes it for him.

I'm attaching it below (it's from H. Peter).

Peter Z., as both Jiri's and my patch fixed the callers of the problem area, and as we have been discussing, there may be more problem areas, I'm thinking the best solution is to just use H. Peter's patch instead. And then we should rename it to copy_from_user_trace().

Like already said; _trace is an absolutely abysmal name. Also you _really_ don't want an unconditional CR2 write in there, that's just stupidly expensive.

Also, this function is called a _LOT_ under certain workloads, I don't know how cheap a CR2 read is, but it had better be really cheap.

Quoted 3 lines

Also, this function is called a _LOT_ under certain workloads, I don't know how cheap a CR2 read is, but it had better be really cheap.

That's a HPA question.

Quoted 4 lines · Steven Rostedt

Quoted 3 lines

Also, this function is called a _LOT_ under certain workloads, I don't know how cheap a CR2 read is, but it had better be really cheap.

Quoted 1 line

That's a HPA question.

We read CR2 in the page fault hot path, so it's on the top of CPU architects' minds and it's reasonably optimized. A couple of cycles IIRC, but would be nice to hear actual numbers.

Quoted 7 lines · Ingo Molnar

Quoted 4 lines · Steven Rostedt

Quoted 3 lines

Also, this function is called a _LOT_ under certain workloads, I don't know how cheap a CR2 read is, but it had better be really cheap.

Quoted 5 lines

Quoted 1 line

That's a HPA question.

We read CR2 in the page fault hot path, so it's on the top of CPU architects' minds and it's reasonably optimized. A couple of cycles IIRC, but would be nice to hear actual numbers.

Yeah, we were discussing this last night on IRC.

And hpa actually meant that the optimization potential was there but no one did do it, except maybe Transmeta. :-)

So the expensive thing is writing to CR2 because it is a serializing instruction. In fact, all writes to control registers except CR8 are serializing.

The reading from CR2 should be cheaper but not as cheap as a normal MOV %reg %reg is. On AMD, MOV %reg, %cr2 is done with microcode so definitely at least a couple of cycles and I'd guess it is not a trivial
MOV on Intel too.

Maybe a way to hide this cost is the OoO, as hpa suggested, depending on
how much parallelism that particular code region can offer (serializing instructions close by).

The bottom line is that if we want hard numbers we probably have to measure.

Hoisting the cr2 read is a no-brainer, might even help performance...

We read CR2 in the page fault hot path, so it's on the top of CPU architects' minds and it's reasonably optimized. A couple of cycles IIRC, but would be nice to hear actual numbers.

Quoted 15 lines · Peter Zijlstra

Quoted 4 lines · H. Peter Anvin

If I'm reading this right we end up going from the page fault tracepoint to copy_from_user_nmi() without going through NMI, and the cr2 corruption is obvious. I guess the assumption that only the NMI path needed to save cr2 is flawed?

It was never assumed it would only go through NMI, but that it would be NMI safe -- and as it turns out, it is that.

What I did assume was that any other callsites would be safe, seeing how they'd already be running in 'normal' contexts.

I had not considered people putting tracepoints _that_ early in the exception paths.

Quoted 2 lines

Note that there's more tracepoints there than the one mentioned.

Well, I was talking about the assumption spelled out in the comment above copy_from_user_nmi() which pretty much states "cr2 is safe because cr2 is saved/restored in the NMI wrappers."

On Fri, 28 Feb 2014, Steven Rostedt wrote:

199.900696: function: __module_address
...
199.900705: function: __kernel_text_address
199.900809: kernel_stack: <stack trace>
=> perf_callchain (ffffffff810d35a2)
=> perf_prepare_sample (ffffffff810cfae3)
=> __perf_event_overflow (ffffffff810d02f4)
=> perf_swevent_overflow (ffffffff810d04e3)
=> perf_swevent_event (ffffffff810d0574)
=> perf_tp_event (ffffffff810d070c)
=> perf_trace_x86_exceptions (ffffffff810341b6)
=> trace_do_page_fault (ffffffff81537702)
=> trace_page_fault (ffffffff81534772)

199.900810: function: perf_output_begin
199.900810: function: __do_page_fault
199.900810: function: __perf_sw_event
199.900810: function: perf_swevent_get_recursion_context

199.900811: function:                down_read_trylock
199.900811: function:                _cond_resched
199.900811: function:                find_vma
199.900811: function:                bad_area

199.900812: function: up_read
199.900812: function: __bad_area_nosemaphore
199.900812: function: is_prefetch
199.900812: function: convert_ip_to_linear
199.900813: function: unhandled_signal
199.900813: function: __printk_ratelimit
199.900813: function: _raw_spin_trylock
199.900813: function: _raw_spin_unlock_irqrestore
199.900814: function: printk
199.900814: function: vprintk_emit

Below is a patch that should fix this. Please remove all other patches and try this out.

Quoted 4 lines · Steven Rostedt

Interesting. Are you doing a perf function trace?

And just in case, can you add this patch and make sure the copy is called by NMI.

199.900682: function: trace_do_page_fault
199.900683: page_fault_user: address=__per_cpu_end
ip=__per_cpu_end error_code=0x6
199.900683: function: perf_swevent_get_recursion_context
199.900684: function: perf_tp_event
199.900684: function: perf_swevent_event
199.900684: function: perf_swevent_overflow
199.900684: function: __perf_event_overflow
199.900685: function: perf_prepare_sample
199.900685: function:
__perf_event_header__init_id
199.900685: function: task_tgid_nr_ns
199.900685: function: perf_event_tid
199.900686: function: __task_pid_nr_ns
199.900686: function: perf_callchain

199.900687: function:             copy_from_user_nmi
199.900687: function:             trace_do_page_fault
199.900687: page_fault_kernel:    address=irq_stack_union

ip=copy_user_generic_string error_code=0x0
199.900688: function: __do_page_fault
199.900688: function: bad_area_nosemaphore
199.900688: function: __bad_area_nosemaphore
199.900689: function: no_context
199.900689: function: fixup_exception
199.900689: function:
search_exception_tables
199.900689: function: search_extable

199.900691: function:             copy_user_handle_tail
199.900691: function:             trace_do_page_fault
199.900691: page_fault_kernel:    address=irq_stack_union

ip=copy_user_handle_tail error_code=0x0
199.900691: function: __do_page_fault
199.900692: function: bad_area_nosemaphore
199.900692: function: __bad_area_nosemaphore
199.900692: function: no_context
199.900692: function: fixup_exception
199.900692: function:
search_exception_tables
199.900692: function: search_extable
199.900693: function: save_stack_trace
199.900693: function: dump_trace
199.900694: function: print_context_stack
199.900694: function: __kernel_text_address
199.900694: function: is_module_text_address
199.900695: function: __module_text_address
199.900695: function: __module_address
199.900695: function: __kernel_text_address
199.900695: function: is_module_text_address
199.900696: function: __module_text_address
199.900696: function: __module_address
...
199.900705: function: __kernel_text_address
199.900809: kernel_stack: <stack trace>
=> perf_callchain (ffffffff810d35a2)
=> perf_prepare_sample (ffffffff810cfae3)
=> __perf_event_overflow (ffffffff810d02f4)
=> perf_swevent_overflow (ffffffff810d04e3)
=> perf_swevent_event (ffffffff810d0574)
=> perf_tp_event (ffffffff810d070c)
=> perf_trace_x86_exceptions (ffffffff810341b6)
=> trace_do_page_fault (ffffffff81537702)
=> trace_page_fault (ffffffff81534772)
199.900810: function: perf_output_begin
199.900810: function: __do_page_fault
199.900810: function: __perf_sw_event
199.900810: function:
perf_swevent_get_recursion_context

199.900811: function:                down_read_trylock
199.900811: function:                _cond_resched
199.900811: function:                find_vma
199.900811: function:                bad_area

199.900812: function: up_read
199.900812: function: __bad_area_nosemaphore
199.900812: function: is_prefetch
199.900812: function: convert_ip_to_linear
199.900813: function: unhandled_signal
199.900813: function: __printk_ratelimit
199.900813: function: _raw_spin_trylock
199.900813: function: _raw_spin_unlock_irqrestore
199.900814: function: printk
199.900814: function: vprintk_emit

Now we need to figure out if the reboot problem and the segfault problem are actually the same... I have a nasty feeling they might be different problems.

Now we need to figure out if the reboot problem and the segfault problem are actually the same... I have a nasty feeling they might be different problems.

I was away from the computer this afternoon and of course I have scores of e-mails on this topic now with lots of competing patches. Is there one in particular I'm supposed to be testing?

Quoted 3 lines · On Fri, 28 Feb 2014 16:18:23 -0500 (EST) Vince Weaver…

I was away from the computer this afternoon and of course I have scores of e-mails on this topic now with lots of competing patches. Is there one in particular I'm supposed to be testing?

I was poking fun at you on IRC for this exact reason:

<rostedt> poor Vince, I keep sending him new patches. "No, don't test this patch, now test this one. Oh wait, try this one instead"
* peterz sees Vince thinking: "stop... sending.. me.. damn... patches... already... !!!11!"
<rostedt> or at least, "Let me finish this test before I cancel it again for another damn patch"
<rostedt> then he's probably doing "I'm not going to run any tests now, until I wait a while to see if there's a new patch to test"

Well while it might appear that I spend all of my days finding perf_event bugs, I actually am a college professor so I do occasionally have to run off to teach a class, meet with students, or write papers/grants for other academics to reject.

It's nice others can reproduce the issue now, it would have saved me a lot of trouble, although now in theory I have a much better handle of how to use/abuse ftrace so I guess it was worth it.

Once the fix gets into git I'm sure the relentless perf_fuzzer will let us know if there are any other issues left. I do look forward to the day when I can leave it running overnight and have a clean syslog the next morning.

Quoted 6 lines

I was poking fun at you on IRC for this exact reason:

<rostedt> poor Vince, I keep sending him new patches. "No, don't test this patch, now test this one. Oh wait, try this one instead"
* peterz sees Vince thinking: "stop... sending.. me.. damn... patches... already... !!!11!"
<rostedt> or at least, "Let me finish this test before I cancel it again for another damn patch"
<rostedt> then he's probably doing "I'm not going to run any tests now, until I wait a while to see if there's a new patch to test"

Well while it might appear that I spend all of my days finding perf_event bugs, I actually am a college professor so I do occasionally have to run off to teach a class, meet with students, or write papers/grants for other academics to reject.

It's nice others can reproduce the issue now, it would have saved me a lot of trouble, although now in theory I have a much better handle of how to use/abuse ftrace so I guess it was worth it.

Once the fix gets into git I'm sure the relentless perf_fuzzer will let us know if there are any other issues left. I do look forward to the day when I can leave it running overnight and have a clean syslog the next morning.

BTW, is the perf_fuzzer code posted somewhere? It sounds like it can be really useful for us to do our own testing too.

Quoted 3 lines · Steven Rostedt

BTW, is the perf_fuzzer code posted somewhere? It sounds like it can be really useful for us to do our own testing too.

I believe it's part of trinity.

http://codemonkey.org.uk/projects/trinity/

Perhaps it should have a "ftracer fuzzer" too?

On Fri, 28 Feb 2014 18:34:00 -0500 (EST)
Vince Weaver <[email protected]> wrote:

But perf_event bug finder is a much more prestigious title than "college professor" ;-)

BTW, is the perf_fuzzer code posted somewhere? It sounds like it can be really useful for us to do our own testing too.

Well, the perf ring buffer is vmalloced, right? That can cause a page fault too.

Quoted 5 lines

What is likely happening is the user page fault is triggering code to do a "perf_callchain" dump, which is calling copy_from_user_nmi() which calls copy_user_generic_string() which is somehow getting the user RBP in the RDI register somehow?

So that code very much relies on the 'recursive' NMI/iret magic from Steve, patch 3f3c8b8c4b2a3 (and assorted fixes later).

If CR2 is getting corrupted; 7fbb98c5cb075 seems relevant.

Peter, does x32 have a slightly different ABI/calling convention that would make any of these patches just slightly 'off'?

arch/x86/mm/fault.c +10 -1

@@ -1267,9 +1269,18 @@ dotraplinkage void __kprobes
 trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	unsigned long address;
 
 	prev_state = exception_enter();
+
+	/*
+	 * The tracepoint processing could trigger another page
+	 * fault (user space callchain reading) and destroy the
+	 * original cr2 value, so read the faulting address now.
+	 */
+	address = read_cr2();
+
 	trace_page_fault_entries(regs, error_code);
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }

Signature · 1 line

1.7.11.7

On Fri, Feb 28, 2014 at 04:33:40PM +0100, Jiri Olsa wrote:

While I like the idea of just pushing up the CR2 read; the below does the read too late still, exception_enter() also has a tracepoint in.

Quoted 4 lines · Peter Zijlstra

On Fri, Feb 28, 2014 at 04:33:40PM +0100, Jiri Olsa wrote:

While I like the idea of just pushing up the CR2 read; the below does the read too late still, exception_enter() also has a tracepoint in.

please check v2, thanks

If so, do we need to hoist the reading of %cr2 all the way into assembly or something else?

Quoted 1 line

Quoted 1 line

[email protected] (after MAIL FROM): 550 5.5.4 <[email protected]>... Domain of sender address [email protected] refused. MX points to hosts without valid addresses. This violates RFC 1035/2181.

Quoted 4 lines · Peter Zijlstra

On Fri, Feb 28, 2014 at 04:33:40PM +0100, Jiri Olsa wrote:

While I like the idea of just pushing up the CR2 read; the below does the read too late still, exception_enter() also has a tracepoint in.

please check v2, thanks

jirka

---
The trace_do_page_fault function trigger tracepoint and then handles the actual page fault.

This could lead to error if the tracepoint caused page fault. The original cr2 value gets lost and the original page fault handler kills current process with SIGSEGV.

This happens if you record page faults with callchain data, the user part of it will cause tracepoint handler to page fault:

  # perf record -g -e exceptions:page_fault_user ls

Fixing this by saving the original cr2 value
and using it after tracepoint handler is done.

v2: Moving the cr2 read before exception_enter, because
it could trigger tracepoint as well.

Reported-by Arnaldo Carvalho de Melo <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Paul Mackerras <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc H. Peter Anvin <[email protected]>

Cc Seiji Aguchi <[email protected]>

Cc Vince Weaver <[email protected]>

Cc Steven Rostedt <[email protected]>

---
 arch/x86/mm/fault.c | 20 +++++++++++++-------
 1 file changed, 13 insertions(+), 7 deletions(-)

arch/x86/mm/fault.c +13 -7

index 9d591c8..dd59031 100644
@@ -1016,11 +1016,11 @@ static inline bool smap_violation(int error_code, struct pt_regs *regs)
  * routines.
  */
 static void __kprobes
-__do_page_fault(struct pt_regs *regs, unsigned long error_code)
+__do_page_fault(struct pt_regs *regs, unsigned long error_code,
+		unsigned long address)
 {
 	struct vm_area_struct *vma;
 	struct task_struct *tsk;
-	unsigned long address;
 	struct mm_struct *mm;
 	int fault;
 	unsigned int flags = FAULT_FLAG_ALLOW_RETRY | FAULT_FLAG_KILLABLE;

@@ -1028,9 +1028,6 @@ __do_page_fault(struct pt_regs *regs, unsigned long error_code)
 	tsk = current;
 	mm = tsk->mm;
 
-	/* Get the faulting address: */
-	address = read_cr2();
-
 	/*
 	 * Detect and handle instructions that would cause a page fault for
 	 * both a tracked kernel page and a userspace page.

@@ -1248,9 +1245,11 @@ dotraplinkage void __kprobes
 do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	/* Get the faulting address: */
+	unsigned long address = read_cr2();
 
 	prev_state = exception_enter();
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }
 

@@ -1267,9 +1266,16 @@ dotraplinkage void __kprobes
 trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	/*
+	 * The exception_enter and tracepoint processing could
+	 * trigger another page faults (user space callchain
+	 * reading) and destroy the original cr2 value, so read
+	 * the faulting address now.
+	 */
+	unsigned long address = read_cr2();
 
 	prev_state = exception_enter();
 	trace_page_fault_entries(regs, error_code);
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }

arch/x86/mm/fault.c +7 -1

@@ -1252,9 +1249,11 @@ dotraplinkage void __kprobes
 do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	/* Get the faulting address: */
+	unsigned long address = read_cr2();
 
 	prev_state = exception_enter();
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }
 

@@ -1271,9 +1270,16 @@ dotraplinkage void __kprobes
 trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	/*
+	 * The exception_enter and tracepoint processing could
+	 * trigger another page faults (user space callchain
+	 * reading) and destroy the original cr2 value, so read

On Tue, Mar 04, 2014 at 04:03:25PM -0800, tip-bot for Jiri Olsa wrote:

FWIW I also prefer this patch.

Quoted 25 lines

arch/x86/mm/fault.c +10 -1

@@ -1252,9 +1249,11 @@ dotraplinkage void __kprobes
 do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	/* Get the faulting address: */
+	unsigned long address = read_cr2();
 
 	prev_state = exception_enter();
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }
 

@@ -1271,9 +1270,16 @@ dotraplinkage void __kprobes
 trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	/*
+	 * The exception_enter and tracepoint processing could
+	 * trigger another page faults (user space callchain
+	 * reading) and destroy the original cr2 value, so read
+	 * the faulting address now.
+	 */
+	unsigned long address = read_cr2();
 

arch/x86/mm/fault.c dotraplinkage void __kprobes · line 1285

Quoted 6 lines

arch/x86/mm/fault.c +1 -1

 	prev_state = exception_enter();
 	trace_page_fault_entries(regs, error_code);
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }

How about also marking these two functions as notrace? That would also avoid getting __mcount calls from before we read CR2.

On Wed, 5 Mar 2014 12:14:15 +0100
Peter Zijlstra <[email protected]> wrote:

Please no! I used tracing of the do_page_fault function all the time. It is very useful.

Quoted 5 lines · Steven Rostedt

On Wed, 5 Mar 2014 12:14:15 +0100
Peter Zijlstra <[email protected]> wrote:

Please no! I used tracing of the do_page_fault function all the time. It is very useful.

Why do you trace do_page_fault and not the __do_page_fault() function? do_page_fault() is a minimal wrapper which doesn't actually do all that much?

Then we better make sure that __do_page_fault() is never inlined. Otherwise, it wont be available to trace.

I'm fine with adding "notrace" to do_page_fault() and to trace_do_page_fault() as long as we also include a "noinline" to __do_page_fault(). Would need a comment stating why that noinline is there though.

Quoted 7 lines · Steven Rostedt

Then we better make sure that __do_page_fault() is never inlined. Otherwise, it wont be available to trace.

I'm fine with adding "notrace" to do_page_fault() and to trace_do_page_fault() as long as we also include a "noinline" to __do_page_fault(). Would need a comment stating why that noinline is there though.

When CONFIG_TRACING there's two callers, which makes it highly unlikely GCC would inline the massive __do_page_fault() function, but sure.

How about something like so then; still has the normal_do_page_fault() thing, although I suppose we could drop that.

It also puts trace_page_fault_entries() and trace_do_page_fault() under CONFIG_TRACING. I could only find the entry_32.S user; I suppose the 64bit one is hidden by CPP goo somewhere?

+trace_errorentry page_fault normal_do_page_fault

Quoted 5 lines

It also puts trace_page_fault_entries() and trace_do_page_fault() under CONFIG_TRACING. I could only find the entry_32.S user; I suppose the 64bit one is hidden by CPP goo somewhere?

+trace_errorentry page_fault normal_do_page_fault

ah found it; its in there. That also means the normal_do_page_fault() thing won't actually compile proper.

Lemme do one with that.

Quoted 5 lines · Steven Rostedt

On Wed, 5 Mar 2014 12:14:15 +0100
Peter Zijlstra <[email protected]> wrote:

Please no! I used tracing of the do_page_fault function all the time. It is very useful.

Why do you trace do_page_fault and not the __do_page_fault() function? do_page_fault() is a minimal wrapper which doesn't actually do all that much?

Quoted 10 lines · Peter Zijlstra

Quoted 5 lines · Steven Rostedt

On Wed, 5 Mar 2014 12:14:15 +0100
Peter Zijlstra <[email protected]> wrote:

Please no! I used tracing of the do_page_fault function all the time. It is very useful.

Why do you trace do_page_fault and not the __do_page_fault() function? do_page_fault() is a minimal wrapper which doesn't actually do all that much?

Here, something like so; then you can still trace your do_page_fault().

It also fixes up trace_page_fault_entries() to not re-read the cr2.

---
 arch/x86/include/asm/traps.h |  2 +-
 arch/x86/kernel/entry_32.S   |  2 +-
 arch/x86/kernel/entry_64.S   |  2 +-
 arch/x86/kernel/kvm.c        |  2 +-
 arch/x86/mm/fault.c          | 21 ++++++++++-----------
 5 files changed, 14 insertions(+), 15 deletions(-)

arch/x86/include/asm/traps.h +0 -0

index 58d66fe06b61..1280f72deea8 100644

arch/x86/include/asm/traps.h +0 -0

 #ifdef CONFIG_TRACING
 dotraplinkage void trace_do_page_fault(struct pt_regs *, unsigned long);
 #endif

arch/x86/kernel/entry_32.S +1 -1

index a2a4f4697889..9a9f64755da8 100644
@@ -1257,7 +1257,7 @@ END(trace_page_fault)
 ENTRY(page_fault)
 	RING0_EC_FRAME
 	ASM_CLAC
-	pushl_cfi $do_page_fault
+	pushl_cfi $normal_do_page_fault
 	ALIGN
 error_code:
 	/* the function address is in %gs's slot on the stack */

arch/x86/kernel/entry_64.S +1 -1

index 1e96c3628bf2..7d49812741ac 100644
@@ -1491,7 +1491,7 @@ zeroentry xen_int3 do_int3
 errorentry xen_stack_segment do_stack_segment
 #endif
 errorentry general_protection do_general_protection
-trace_errorentry page_fault do_page_fault
+trace_errorentry page_fault normal_do_page_fault
 #ifdef CONFIG_KVM_GUEST
 errorentry async_page_fault do_async_page_fault
 #endif

arch/x86/kernel/kvm.c +1 -1

index 713f1b3bad52..9e7db22ec437 100644
@@ -259,7 +259,7 @@ do_async_page_fault(struct pt_regs *regs, unsigned long error_code)
 
 	switch (kvm_read_and_reset_pf_reason()) {
 	default:
-		do_page_fault(regs, error_code);
+		normal_do_page_fault(regs, error_code);
 		break;
 	case KVM_PV_REASON_PAGE_NOT_PRESENT:
 		/* page is swapped out by the host. */

arch/x86/mm/fault.c +0 -0

index e7fa28bf3262..576cfc3d0086 100644

arch/x86/mm/fault.c +10 -11

-__do_page_fault(struct pt_regs *regs, unsigned long error_code,
-		unsigned long address)
+do_page_fault(struct pt_regs *regs, unsigned long error_code, unsigned long address)
 {
 	struct vm_area_struct *vma;
 	struct task_struct *tsk;

@@ -1245,28 +1244,28 @@ __do_page_fault(struct pt_regs *regs, unsigned long error_code,
 	up_read(&mm->mmap_sem);
 }
 
-dotraplinkage void __kprobes
-do_page_fault(struct pt_regs *regs, unsigned long error_code)
+dotraplinkage void __kprobes notrace
+normal_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
 	/* Get the faulting address: */
 	unsigned long address = read_cr2();
 
 	prev_state = exception_enter();
-	__do_page_fault(regs, error_code, address);
+	do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }
 
-static void trace_page_fault_entries(struct pt_regs *regs,
+static void trace_page_fault_entries(unsigned long address, struct pt_regs *regs,
 				     unsigned long error_code)
 {
 	if (user_mode(regs))
-		trace_page_fault_user(read_cr2(), regs, error_code);
+		trace_page_fault_user(address, regs, error_code);
 	else
-		trace_page_fault_kernel(read_cr2(), regs, error_code);
+		trace_page_fault_kernel(address, regs, error_code);
 }
 
-dotraplinkage void __kprobes
+dotraplinkage void __kprobes notrace
 trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;

@@ -1279,7 +1278,7 @@ trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 	unsigned long address = read_cr2();
 
 	prev_state = exception_enter();
-	trace_page_fault_entries(regs, error_code);
-	__do_page_fault(regs, error_code, address);
+	trace_page_fault_entries(address, regs, error_code);
+	do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }

Quoted 1 line

static void __kprobes

Still requires the "noinline" above

Quoted 3 lines · Steven Rostedt

Quoted 1 line

static void __kprobes

Still requires the "noinline" above

Trim trim trim trim your emails...

also, you're like 3 version behind.

OK, I have to admit to having lost track of this thread. Please let me know when there is anything actionable for me.

Quoted 2 lines · H. Peter Anvin

OK, I have to admit to having lost track of this thread. Please let me know when there is anything actionable for me.

lkml.kernel.org/r/[email protected]

Was the latest; Rostedt are you good with that one? If so I suppose I should make it a proper patch and get hpa to look at it :-)

The trace_do_page_fault function trigger tracepoint and then handles the actual page fault.

This could lead to error if the tracepoint caused page fault. The original cr2 value gets lost and the original page fault handler kills current process with SIGSEGV.

This happens if you record page faults with callchain data, the user part of it will cause tracepoint handler to page fault:

  # perf record -g -e exceptions:page_fault_user ls

Fixing this by saving the original cr2 value and using it after tracepoint handler is done.

Cc Peter Zijlstra <[email protected]>

Cc Paul Mackerras <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc H. Peter Anvin <[email protected]>

Cc Seiji Aguchi <[email protected]>

---
 arch/x86/mm/fault.c | 25 ++++++++++++++++++-------
 1 file changed, 18 insertions(+), 7 deletions(-)

arch/x86/mm/fault.c +18 -7

index 9d591c8..52fad6c 100644
@@ -1016,11 +1016,11 @@ static inline bool smap_violation(int error_code, struct pt_regs *regs)
  * routines.
  */
 static void __kprobes
-__do_page_fault(struct pt_regs *regs, unsigned long error_code)
+__do_page_fault(struct pt_regs *regs, unsigned long error_code,
+		unsigned long address)
 {
 	struct vm_area_struct *vma;
 	struct task_struct *tsk;
-	unsigned long address;
 	struct mm_struct *mm;
 	int fault;
 	unsigned int flags = FAULT_FLAG_ALLOW_RETRY | FAULT_FLAG_KILLABLE;

@@ -1028,9 +1028,6 @@ __do_page_fault(struct pt_regs *regs, unsigned long error_code)
 	tsk = current;
 	mm = tsk->mm;
 
-	/* Get the faulting address: */
-	address = read_cr2();
-
 	/*
 	 * Detect and handle instructions that would cause a page fault for
 	 * both a tracked kernel page and a userspace page.

@@ -1248,9 +1245,14 @@ dotraplinkage void __kprobes
 do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	unsigned long address;
 
 	prev_state = exception_enter();
-	__do_page_fault(regs, error_code);
+
+	/* Get the faulting address: */
+	address = read_cr2();
+
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }
 

@@ -1267,9 +1269,18 @@ dotraplinkage void __kprobes
 trace_do_page_fault(struct pt_regs *regs, unsigned long error_code)
 {
 	enum ctx_state prev_state;
+	unsigned long address;
 
 	prev_state = exception_enter();
+
+	/*
+	 * The tracepoint processing could trigger another page
+	 * fault (user space callchain reading) and destroy the
+	 * original cr2 value, so read the faulting address now.
+	 */
+	address = read_cr2();
+
 	trace_page_fault_entries(regs, error_code);
-	__do_page_fault(regs, error_code);
+	__do_page_fault(regs, error_code, address);
 	exception_exit(prev_state);
 }

Signature · 1 line

1.7.11.7