[RFC PATCH 0/1] Exclude real mode code from ftrace

If the function tracer is enabled when starting a guest, we get the 
below oops:

------------[ cut here ]------------
Delta way too big! 17582052940437522358 ts=17582052944931114496 write stamp = 4493592138
Oops: Bad interrupt in KVM entry/exit code, sig: 6 [#1]
LE SMP NR_CPUS=2048 NUMA PowerNV
Modules linked in:
CPU: 0 PID: 1380 Comm: qemu-system-ppc Not tainted 4.16.0-rc3-nnr+ #148
NIP:  c0000000002635f8 LR: c0000000002635f4 CTR: c0000000001c1384
REGS: c0000000fffd1d80 TRAP: 0700   Not tainted  (4.16.0-rc3-nnr+)
MSR:  9000000002823003 <SF,HV,VEC,VSX,FP,ME,RI,LE>  CR: 28242222  XER: 20000000
CFAR: c000000000144f94 SOFTE: 3 
GPR00: c0000000002635f4 c0000000a26931d0 c0000000013fbe00 0000000000000058 
GPR04: 0000000000000001 0000000000000000 0000000000000001 0000000000000000 
GPR08: 00000000fe8d0000 c000000001287368 c000000001287368 
0000000028242224 GPR12: 0000000000002000 c00000000fac0000 
c00000000012cd04 c0000000f0279a00 GPR16: c0000000a26938e0 
c000000000de2044 c0000000015c5488 0000000000000000 GPR20: 
0000000000000000 0000000000000001 0000000000000000 0000000000000001 
GPR24: 0000000000000001 0000000000000000 0000000000000000 
0000000000000003 GPR28: 0000000000000000 0000000000000000 
00000000000003e8 c0000000a2693260 NIP [c0000000002635f8] 
rb_handle_timestamp+0x88/0x90
LR [c0000000002635f4] rb_handle_timestamp+0x84/0x90
Call Trace:
[c0000000a26931d0] [c0000000002635f4] rb_handle_timestamp+0x84/0x90 (unreliable)
[c0000000a2693240] [c000000000266d84] ring_buffer_lock_reserve+0x174/0x5d0
[c0000000a26932b0] [c0000000002728a0] trace_function+0x50/0x190
[c0000000a2693310] [c00000000027f000] function_trace_call+0x140/0x170
[c0000000a2693340] [c000000000064c80] ftrace_call+0x4/0xb8
[c0000000a2693510] [c00000000012720c] kvmppc_hv_entry+0x148/0x164
[c0000000a26935b0] [c000000000126ce0] kvmppc_call_hv_entry+0x28/0x124
[c0000000a2693620] [c00000000011dd84] __kvmppc_vcore_entry+0x13c/0x1b8
[c0000000a26937f0] [c00000000011a8c0] kvmppc_run_core+0xec0/0x1e50
[c0000000a26939b0] [c00000000011c6e4] kvmppc_vcpu_run_hv+0x484/0x1270
[c0000000a2693b30] [c0000000000f8ea8] kvmppc_vcpu_run+0x38/0x50
[c0000000a2693b50] [c0000000000f4a8c] kvm_arch_vcpu_ioctl_run+0x28c/0x380
[c0000000a2693be0] [c0000000000e6978] kvm_vcpu_ioctl+0x4c8/0x780
[c0000000a2693d40] [c0000000003e64e8] do_vfs_ioctl+0xd8/0x900
[c0000000a2693de0] [c0000000003e6d7c] SyS_ioctl+0x6c/0x100
[c0000000a2693e30] [c00000000000bc60] system_call+0x58/0x6c
Instruction dump:
2f890000 409effd4 e8c300b0 e8bf0000 39200001 3ce2ffc9 3c62ffc2 38e78808 
38638058 992a7032 4bee1939 60000000 <0fe00000> 4bffffa4 3c4c011a 38428800 
---[ end trace 6c43107948f7546d ]---

The KVM entry code updates the timebase register based on the guest's 
tb_offset, which upsets ftrace ring buffer time stamps resulting in a 
WARN_ONCE() in rb_handle_timestamp(). Furthermore, WARN() inserts a trap 
instruction which is now hit while we are in guest MMU context, 
resulting in the oops above.

The obvious way to address this is to exclude all KVM C code that can be 
run when we are in KVM_GUEST_MODE_HOST_HV from ftrace using the 
'notrace' annotation (*). But, there are a few problems doing that:
- the list grows quickly since we need to blacklist not just the top 
  level function, but every other function which those can call and any 
  and all functions that those can in turn call, and so on...
- even if we do the above, it is hard to ensure that all functions are 
  covered and that this continues to be the case due to code refactoring 
  adding new functions.

The other ways to handle this need a slightly larger hammer:
1. exclude all KVM code from ftrace
2. exclude all real mode code from ftrace

(1) is fairly easy to do, but is still not sufficient since we do call 
into various mm/ helpers and they will need to be additionally excluded.  
It also ends up excluding a lot of KVM code that can still be traced.

(2) is the approach implemented by the subsequent patch (+) and looks 
like a reasonable tradeoff since it additionally excludes all real mode 
code, rather than just the KVM code. However, I am not completely sure 
how much real mode C code we have, that we would like to be able to 
trace. So, it would be good to hear what is preferable.

Please let me know your thoughts.


Thanks,
Naveen

-
(*) Afaics, KVM real mode code is not segregated into a separate file 
and is not trivial to do. If this is not true, then this may be an 
option to consider.
(+) This RFC only handles -mprofile-kernel, and would need to be updated 
to deal with other ftrace entry code.



Naveen N. Rao (1):
  powerpc/ftrace: Exclude real mode code from being traced

 arch/powerpc/kernel/trace/ftrace_64_mprofile.S | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

-- 
2.16.1

We can't take a trap in most parts of real mode code. Instead of adding
the 'notrace' annotation to all C functions that can be invoked from
real mode, detect that we are in real mode on ftrace entry and return
back.

Signed-off-by: Naveen N. Rao <redacted>
---
This RFC only handles -mprofile-kernel to demonstrate the approach being 
considered. We will need to handle other ftrace entry if we decide to 
continue down this path.

- Naveen


 arch/powerpc/kernel/trace/ftrace_64_mprofile.S | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/arch/powerpc/kernel/trace/ftrace_64_mprofile.S b/arch/powerpc/kernel/trace/ftrace_64_mprofile.S
index 3f3e81852422..ecc0e8e38ead 100644
--- a/arch/powerpc/kernel/trace/ftrace_64_mprofile.S
+++ b/arch/powerpc/kernel/trace/ftrace_64_mprofile.S

@@ -56,6 +56,21 @@ _GLOBAL(ftrace_caller)
 
 	/* Load special regs for save below */
 	mfmsr   r8
+
+	/* Only proceed if we are not in real mode and can take interrupts */
+	andi.	r9, r8, MSR_IR|MSR_DR|MSR_RI
+	cmpdi	r9, MSR_IR|MSR_DR|MSR_RI
+	beq	1f
+	mflr	r8
+	mtctr	r8
+	REST_GPR(9, r1)
+	REST_GPR(8, r1)
+	addi	r1, r1, SWITCH_FRAME_SIZE
+	ld	r0, LRSAVE(r1)
+	mtlr	r0
+	bctr
+
+1:
 	mfctr   r9
 	mfxer   r10
 	mfcr	r11

-- 
2.16.1

On Wed,  7 Mar 2018 22:16:19 +0530
"Naveen N. Rao" [off-list ref] wrote:

We can't take a trap in most parts of real mode code. Instead of adding
the 'notrace' annotation to all C functions that can be invoked from
real mode, detect that we are in real mode on ftrace entry and return
back.

Signed-off-by: Naveen N. Rao <redacted>
---
This RFC only handles -mprofile-kernel to demonstrate the approach being 
considered. We will need to handle other ftrace entry if we decide to 
continue down this path.

I do prefer this trade off.

OK, I assume this check and branch is negligible compared to the mfmsr
call?

-- Steve

+	mflr	r8
+	mtctr	r8
+	REST_GPR(9, r1)
+	REST_GPR(8, r1)
+	addi	r1, r1, SWITCH_FRAME_SIZE
+	ld	r0, LRSAVE(r1)
+	mtlr	r0
+	bctr
+
+1:
 	mfctr   r9
 	mfxer   r10
 	mfcr	r11

Hi Steve,

Steven Rostedt wrote:

On Wed,  7 Mar 2018 22:16:19 +0530
"Naveen N. Rao" [off-list ref] wrote:
=20

quoted

We can't take a trap in most parts of real mode code. Instead of adding
the 'notrace' annotation to all C functions that can be invoked from
real mode, detect that we are in real mode on ftrace entry and return
back.
=20
Signed-off-by: Naveen N. Rao <redacted>
---
This RFC only handles -mprofile-kernel to demonstrate the approach being=

=20

quoted

considered. We will need to handle other ftrace entry if we decide to=20
continue down this path.

=20
I do prefer this trade off.

Great, thanks!

=20
=20

quoted

diff --git a/arch/powerpc/kernel/trace/ftrace_64_mprofile.S b/arch/power=

pc/kernel/trace/ftrace_64_mprofile.S

quoted

index 3f3e81852422..ecc0e8e38ead 100644

--- a/arch/powerpc/kernel/trace/ftrace_64_mprofile.S
+++ b/arch/powerpc/kernel/trace/ftrace_64_mprofile.S

@@ -56,6 +56,21 @@ _GLOBAL(ftrace_caller)

=20
 	/* Load special regs for save below */
 	mfmsr   r8
+
+	/* Only proceed if we are not in real mode and can take interrupts */
+	andi.	r9, r8, MSR_IR|MSR_DR|MSR_RI
+	cmpdi	r9, MSR_IR|MSR_DR|MSR_RI
+	beq	1f

=20
OK, I assume this check and branch is negligible compared to the mfmsr
call?

Yes, that's negligible.
Though, to be honest, I will have to introduce a 'mfmsr' for the older=20
-pg variant. I still think that the improved reliability far outweighs=20
the minor slowdown there.

- Naveen

=

On Thu, 08 Mar 2018 00:07:07 +0530
"Naveen N. Rao" [off-list ref] wrote:

Yes, that's negligible.
Though, to be honest, I will have to introduce a 'mfmsr' for the older 
-pg variant. I still think that the improved reliability far outweighs 
the minor slowdown there.

In that case, can you introduce a read_mostly variable that can be
tested before calling the mfmsr. Why punish normal ftrace tracing if
kvm is not enabled or running?

Both should probably have an #ifdef CONFIG_KVM encapsulating the code.

-- Steve

"Naveen N. Rao" [off-list ref] writes:

We can't take a trap in most parts of real mode code. Instead of adding
the 'notrace' annotation to all C functions that can be invoked from
real mode, detect that we are in real mode on ftrace entry and return
back.

Signed-off-by: Naveen N. Rao <redacted>
---
This RFC only handles -mprofile-kernel to demonstrate the approach being 
considered. We will need to handle other ftrace entry if we decide to 
continue down this path.

Paul and I were talking about having a paca flag for this, ie.
paca->safe_to_ftrace (or whatever). I'm not sure if you've talked to
him and decided this is a better approach.

I guess I'm 50/50 on which is better, they both have pluses and minuses.

cheers

Michael Ellerman wrote:

"Naveen N. Rao" [off-list ref] writes:
=20

quoted

We can't take a trap in most parts of real mode code. Instead of adding
the 'notrace' annotation to all C functions that can be invoked from
real mode, detect that we are in real mode on ftrace entry and return
back.

Signed-off-by: Naveen N. Rao <redacted>
---
This RFC only handles -mprofile-kernel to demonstrate the approach being=

=20

quoted

considered. We will need to handle other ftrace entry if we decide to=20
continue down this path.

=20
Paul and I were talking about having a paca flag for this, ie.
paca->safe_to_ftrace (or whatever). I'm not sure if you've talked to
him and decided this is a better approach.
=20
I guess I'm 50/50 on which is better, they both have pluses and minuses.

Thanks, I hadn't spoken to Paul, but I now think that this is probably=20
the better approach to take.

My earlier assumption was that we have other scenarios when we are in=20
realmode (specifically with MSR_RI unset) where we won't be able to=20
recover from a trap, during function tracing (*). I did a set of=20
experiments yesterday to verify that, but I was not able to uncover any=20
such scenarios with my brief testing. So, we seem to be functioning just=20
fine while tracing realmode C code, except for KVM.

As such, rather than blacklisting all realmode code, I think it is=20
better to be selective and just disable the tracer for KVM since we know=20
we can't take a trap there. We will be able to use the same approach if=20
we uncover additional scenarios where we can't use function tracing. I=20
will look at implementing a paca field for this purpose.

I also noticed that even with an unexpected timebase, we still seem to=20
recover just fine with a simple change:

--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c

@@ -2629,8 +2629,8 @@ static noinline void
 rb_handle_timestamp(struct ring_buffer_per_cpu *cpu_buffer,
                    struct rb_event_info *info)
 {
-       WARN_ONCE(info->delta > (1ULL << 59),
-                 KERN_WARNING "Delta way too big! %llu ts=3D%llu write sta=

mp =3D %llu\n%s",
+       if (info->delta > (1ULL << 59))
+               pr_warn_once("Delta way too big! %llu ts=3D%llu write stamp=
 =3D %llu\n%s",
                  (unsigned long long)info->delta,
                  (unsigned long long)info->ts,
                  (unsigned long long)cpu_buffer->write_stamp,


This allowed the virtual machine to boot and we were able to trace the=20
rest of KVM C code. I only just did a boot test, so I'm not sure if=20
there are other scenarios where things can go wrong.

Steve,
Would you be willing to accept a patch like the above? Since we seem to=20
handle the larger delta just fine, I think the above change should be=20
fine?

I will still work on excluding KVM C code from being traced, but the=20
advantage with the above patch is that we will be able to trace KVM C=20
code with a small change if necessary.


- Naveen

---
(*) putting on my kprobe hat

=

Steven Rostedt wrote:

On Thu, 08 Mar 2018 00:07:07 +0530
"Naveen N. Rao" [off-list ref] wrote:
=20

quoted

Yes, that's negligible.
Though, to be honest, I will have to introduce a 'mfmsr' for the older=20
-pg variant. I still think that the improved reliability far outweighs=20
the minor slowdown there.

=20
In that case, can you introduce a read_mostly variable that can be
tested before calling the mfmsr. Why punish normal ftrace tracing if
kvm is not enabled or running?
=20
Both should probably have an #ifdef CONFIG_KVM encapsulating the code.

Agreed. My previous intent was to exclude all realmode code from ftrace,=20
but I now think it is better to only exclude the KVM path. So, I will=20
make it specific to KVM.

- Naveen

=

"Naveen N. Rao" [off-list ref] writes:

Michael Ellerman wrote:

quoted

"Naveen N. Rao" [off-list ref] writes:

quoted

We can't take a trap in most parts of real mode code. Instead of adding
the 'notrace' annotation to all C functions that can be invoked from
real mode, detect that we are in real mode on ftrace entry and return
back.

Signed-off-by: Naveen N. Rao <redacted>
---
This RFC only handles -mprofile-kernel to demonstrate the approach being 
considered. We will need to handle other ftrace entry if we decide to 
continue down this path.

Paul and I were talking about having a paca flag for this, ie.
paca->safe_to_ftrace (or whatever). I'm not sure if you've talked to
him and decided this is a better approach.

I guess I'm 50/50 on which is better, they both have pluses and minuses.

Thanks, I hadn't spoken to Paul, but I now think that this is probably 
the better approach to take.

OK.

My earlier assumption was that we have other scenarios when we are in 
realmode (specifically with MSR_RI unset) where we won't be able to 
recover from a trap, during function tracing (*). I did a set of 
experiments yesterday to verify that, but I was not able to uncover any 
such scenarios with my brief testing. So, we seem to be functioning just 
fine while tracing realmode C code, except for KVM.

Hmm. If MSR_RI is clear then that should indicate that you can't recover
from an interrupt, typically because you'd lose state in SRR0/1. So I
would expect things to go badly in that case.

But that's sort of orthogonal to real mode. Real mode is different and
we do need to be careful, but a blanket ban on tracing in real mode
might be too broad.

The problem with KVM is that you're running in real mode (MMU off), in
the host kernel, but with the MMU context of the guest loaded. So if you
do anything that turns the MMU on, like a WARN_ON(), then all of a
sudden you're running guest kernel code.

As such, rather than blacklisting all realmode code, I think it is 
better to be selective and just disable the tracer for KVM since we know 
we can't take a trap there. We will be able to use the same approach if 
we uncover additional scenarios where we can't use function tracing. I 
will look at implementing a paca field for this purpose.

Thanks. I think it could work well.

We could also use it during early boot, ie. the flag starts out false,
and in the kexec/kdump path as well.

cheers

Michael Ellerman wrote:

"Naveen N. Rao" [off-list ref] writes:

quoted

My earlier assumption was that we have other scenarios when we are in=20
realmode (specifically with MSR_RI unset) where we won't be able to=20
recover from a trap, during function tracing (*). I did a set of=20
experiments yesterday to verify that, but I was not able to uncover=20
any such scenarios with my brief testing. So, we seem to be=20
functioning just fine while tracing realmode C code, except for KVM.

=20
Hmm. If MSR_RI is clear then that should indicate that you can't recover
from an interrupt, typically because you'd lose state in SRR0/1. So I
would expect things to go badly in that case.

Yes, so it looks like we aren't calling into any C code (that isn't=20
already annotated with 'notrace') with MSR_RI unset. At least, with the=20
usual interrupt handling on powernv. I tested this by putting a 'trap'=20
in the function tracer callback after the recursion test. This forces a=20
trap for each function that we trace non-recursively.

There may be other paths where we do so, but it isn't as pervasive as I=20
previously thought. So, we should be able to exclude those paths using=20
the paca field, as and when we find them.

- Naveen

=