Re: Recent aarch64 kprobes and uprobes patch systemtap testing

[William Cohen <wcohen@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 4811 bytes --]

On 12/10/2015 04:12 PM, David Long wrote:
> On 12/10/2015 03:24 PM, William Cohen wrote:

>> The fslatency-nd and fsslower-nd tests need further investigation:
>>
>> PASS: ./systemtap.examples/lwtools/fslatency-nd build
>> meta taglines 'test_installcheck: stap fslatency-nd.stp 1 1' tag 'test_installcheck' value 'stap fslatency-nd.stp 1 1'
>> attempting command stap fslatency-nd.stp 1 1
>> OUT ERROR: read fault [man error::fault] at 0x0000000000000034 (addr) near operator '@cast' at fslatency-nd.stp:66:15
>> Tracing FS sync reads and writes... Output every 1 secs.
>> WARNING: Number of errors: 1, skipped probes: 1
>> WARNING: /root/systemtap_write/install/bin/staprun exited with status: 1
>> Pass 5: run failed.  [man error::pass5]
>> child process exited abnormally
>> RC 1
>> FAIL: ./systemtap.examples/lwtools/fslatency-nd run
>>
>> PASS: ./systemtap.examples/lwtools/fsslower-nd build
>> meta taglines 'test_installcheck: stap fsslower-nd.stp -c "sleep 1"' tag 'test_installcheck' value 'stap fsslower-nd.stp -c "sleep 1"'
>> attempting command stap fsslower-nd.stp -c "sleep 1"
>> OUT ERROR: read fault [man error::fault] at 0x0000000000000034 (addr) near operator '@cast' at fsslower-nd.stp:68:15
>> Tracing FS sync reads and writes slower than 10 ms... Hit Ctrl-C to end.
>> TIME     PID    COMM             FUNC           SIZE     LAT(ms)
>> WARNING: Number of errors: 1, skipped probes: 1
>> WARNING: /root/systemtap_write/install/bin/staprun exited with status: 1
>> Pass 5: run failed.  [man error::pass5]
>> child process exited abnormally
>> RC 1
>> FAIL: ./systemtap.examples/lwtools/fsslower-nd run

> 
> Cool. Wish I could make sense of systemtap error messages.
> 
>  At Will Deacon's suggested I tested probing the instruction in __copy_to_user that can cause a captured kernel exception when an application passes in a bad buffer address.  Unfortunately the result was a hang.  So copy_to/from user is going to have to be blacklisted for now, unless there turns out to be a simple fix. I'm worried there might be other places in the kernel where an otherwise probeable instruction might be expected to generate an exception.
> 
> -dl
> 
> 
> 

Hi Dave and Pratyush,

I did some more experimentation with the fslatency-nd and fsslow-nd tests to see what is going on.  The problem seems to be related to the return probes.  I have a small reproducer attached which runs fine on x86_64 machine.  However on aarch64 it has the bogus read because some of the argument registers have changed value

# ../install/bin/stap ./aarch64_retkprobe_issue2.stp 
ERROR: read fault [man error::fault] at 0x0000000000000034 (addr) near operator '@cast' at ./aarch64_retkprobe_issue2.stp:13:7
pc : [<fffffe000021e37c>] lr : [<fffffe000021eb64>] pstate: 80000145
sp : fffffe00bad7be30
x29: fffffe00bad7be30 x28: fffffe00bad78000 
x27: fffffe0000912000 x26: 000000000000003f 
x25: 000000000000011d x24: 0000000000000015 
x23: 0000000080000000 x22: 000003fff82b9760 
x21: fffffe00bad7bec8 x20: 0000000000002004 
x19: fffffe01b716e100 x18: 000003fff82b8160 
x17: 000003ff849bf0a0 x16: fffffe000021f4a0 
x15: 0000000000000004 x14: 000003fff82bb910 
x13: 0000000000000001 x12: 000003ff7d75f200 
x11: 00000000003d0f00 x10: 000003ff849b7af4 
x9 : 0000000000000028 x8 : 0000000000000020 
x7 : fffffe00bc5c3600 x6 : 0000000000000000 
x5 : 0000000000000000 x4 : 0000000000000000 
x3 : fffffe00bad7bec8 x2 : 0000000000002004 
x1 : 000003fff82b9760 x0 : fffffe01b716e100 

pc : [<fffffe000021e37c>] lr : [<fffffe000009fbe0>] pstate: 60000145
sp : fffffe00bad7be30
x29: fffffe00bad7be30 x28: fffffe00bad78000 
x27: fffffe0000912000 x26: 000000000000003f 
x25: 000000000000011d x24: 0000000000000015 
x23: 0000000080000000 x22: 000003fff82b9760 
x21: fffffe00bad7bec8 x20: 0000000000002004 
x19: fffffe01b716e100 x18: 000003fff82b8160 
x17: 000003ff849bf0a0 x16: fffffe000021f4a0 
x15: 0000000000000004 x14: 000003fff82bb910 
x13: 0000000000000001 x12: 000003ff7d75f200 
x11: 00000000003d0f00 x10: 000003ff849b7af4 
x9 : 0000000000000028 x8 : 0000000000000020 
x7 : fffffe00bc5c3600 x6 : 000003fff82b976c 
x5 : 000003fff82b976c x4 : 0000000000000000 
x3 : 0000000000000000 x2 : 0000000000000000 
x1 : 0000000000000000 x0 : 000000000000000c 

WARNING: Number of errors: 1, skipped probes: 1
WARNING: /root/systemtap_write/install/bin/staprun exited with status: 1
Pass 5: run failed.  [man error::pass5]

Comment the return probe with a '#' at the beginning of the line with "kprobe.function("__vfs_read").return," and the script runs fine.  The systemtap pointer_arg() doesn't take into account that the register might be used as a scratch register and the value changed after entry into the function.  This is an issue with the systemtap scripts. I have patched the systemtap scripts to addresss this issue..

-Will

[-- Attachment #2: aarch64_retkprobe_issue2.stp --]
[-- Type: text/plain, Size: 473 bytes --]

# The return probe appears to cause this reproducer to crash
# kprobe.function("__vfs_read").return causes a read fault
# comment out the kprobe.function("__vfs_read").return and the
# script runs without error
probe
      kprobe.function("__vfs_read").return,
      kprobe.function("__vfs_read")
{
	# Skip the call if new_sync_read() wouldn't be called.
	file = pointer_arg(1)
	if (file) {
		print_regs();
 		if(@cast(file, "file")->f_op->read) {
			next
		}
	}
	exit()
}