Workarounds for very useful developer userspace tracing scripts

Workarounds for very useful developer userspace tracing scripts

[argetek senvx]

Hi guys,

I know that the userspace tracing is in works, and I keep checking the
lists to see if any progress has been made.  But I am tired of going
over to my Solaris VM all the time to execute the these three DTrace
scripts or variations thereof:

        -  Which system calls a particular userspace function in a
           process invokes

        -  Aggregate user stacks calling a particular function in
           userspace

        -  Good ol' userspace function trace with call flow
           indentation.

I was wondering if there's any guess as to when the userspace tracing
will become available.  But in the meantime, are there any workarounds
for these scripts that I could use on Linux?

Regards,

      ~ argetek

Re: Workarounds for very useful developer userspace tracing scripts

[Jim Keniston]

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

On Fri, 2007-06-08 at 18:07 +0100, argetek senvx wrote:
> Hi guys,
> 
> I know that the userspace tracing is in works, and I keep checking the
> lists to see if any progress has been made.  But I am tired of going
> over to my Solaris VM all the time to execute the these three DTrace
> scripts or variations thereof:
> 
>         -  Which system calls a particular userspace function in a
>            process invokes
> 
>         -  Aggregate user stacks calling a particular function in
>            userspace
> 
>         -  Good ol' userspace function trace with call flow
>            indentation.
> 
> I was wondering if there's any guess as to when the userspace tracing
> will become available.  But in the meantime, are there any workarounds
> for these scripts that I could use on Linux?
> 
> Regards,
> 
>       ~ argetek

The kernel infrastructure that SystemTap is exploiting for user-space
tracing (utrace and uprobes) is in pretty good shape.  For example, a
kernel module that provides a CRUDE solution for your #1 request above
is attached (argetek1.c).

BTW, #3 (also CRUDE) is in our test suite.  #2 would benefit from
SystemTap's ability to use a stack trace as an index to an associative
array.

Sample usage: You want to trace the syscalls called by function
do_some_syscalls() in the attached program tracemyscs.c.

Window #1
$ objdump -d tracemysc | grep '<do_some_syscalls>:'
080485d4 <do_some_syscalls>:
$ ./tracemysc 2
I am process 9084.  Attach and press Enter:

Window #2
# insmod argetek1.ko func=0x080485d4 pid=9084

Window #1
[Enter]
2 interations in 0.023112 sec
$

Window #2
# rmmod argetek1

What's logged to /var/log/messages is something like this:

Jun  8 11:47:06 ibm-ni9dztukfq8 kernel: Registering uprobe on pid 9084,
vaddr 0x80485d4
Jun  8 11:47:06 ibm-ni9dztukfq8 kernel: Registering return probe on pid
9084, vaddr 0x80485d4
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: Function at 0x80485d4 called
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #45 returns
0x804a000
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #45 returns
0x806b000
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #5 returns 0x3
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #197 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #192 returns
0xb7fcb000
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #4 returns 0x12
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #6 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #91 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #10 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: Function at 0x80485d4 returns
0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: Function at 0x80485d4 called
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #5 returns 0x3
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #197 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #192 returns
0xb7fcb000
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #4 returns 0x12
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #6 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #91 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 9084: syscall #10 returns 0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: Function at 0x80485d4 returns
0x0
Jun  8 11:47:12 ibm-ni9dztukfq8 kernel: 
Jun  8 11:47:21 ibm-ni9dztukfq8 kernel: Unregistering probes on pid
9084, vaddr 0x80485d4

A more friendly interface (a la strace or ltrace) is left as an exercise
for SystemTap. :-}

http://sourceware.org/ml/systemtap/2007-q2/msg00399.html has the latest
uprobes patches and a pointer to utrace.

Jim Keniston

[-- Attachment #2: argetek1.c --]
[-- Type: text/x-csrc, Size: 3910 bytes --]

/* uretprobe_example.c, adjusted to add syscall tracing */
#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>
#include <linux/uprobes.h>
#include <linux/ptrace.h>
#include <linux/utrace.h>
#include <linux/err.h>

/*
 * Usage:
 * insmod argetek1.ko pid=<pid> func=<addr>
 * where <pid> identifies the probed process, and <addr> is the virtual
 * address of the probed function.
 *
 * Traces calls and returns from the specified function, plus calls
 * and returns of system calls made by the function and its callees.
 */

static int pid = 0;
module_param(pid, int, 0);
MODULE_PARM_DESC(pid, "pid");

static long func = 0;
module_param(func, long, 0);
MODULE_PARM_DESC(func, "func");

static struct uprobe usp;
static struct uretprobe rp;
struct task_struct *tracee;
struct utrace_attached_engine *engine;

static u32 report_death(struct utrace_attached_engine *e,
	struct task_struct *tsk)
{
	BUG_ON(tsk != tracee);
	engine = NULL;
	return (UTRACE_ACTION_NEWSTATE | UTRACE_ACTION_DETACH);
}

static u32 report_syscall_entry(struct utrace_attached_engine *engine,
	struct task_struct *tsk, struct pt_regs *regs)
{
	printk("%d: syscall #%ld ", current->pid, regs->orig_eax);
	return UTRACE_ACTION_RESUME;
}

static u32 report_syscall_exit(struct utrace_attached_engine *engine,
	struct task_struct *tsk, struct pt_regs *regs)
{
	printk("returns %#lx\n", regs_return_value(regs));
	return UTRACE_ACTION_RESUME;
}

static const struct utrace_engine_ops utrace_ops =
{
	.report_syscall_entry = report_syscall_entry,
	.report_syscall_exit = report_syscall_exit,
	.report_death = report_death
};

static int attach_engine(void)
{
	unsigned long flags;
	tracee = current;
	engine = utrace_attach(tracee, UTRACE_ATTACH_CREATE, &utrace_ops, NULL);
	if (IS_ERR(engine)) {
		long err = PTR_ERR(engine);
		printk(KERN_ERR "utrace_attach() failed; returned %ld\n", err);
		return (int) err;
	}
	flags = engine->flags;
	flags |= UTRACE_EVENT(DEATH);
	utrace_set_flags(tracee, engine, flags);
	return 0;
}

static void enable_syscall_trace(void)
{
	unsigned long flags;
	if (!engine)
		(void) attach_engine();
	if (IS_ERR(engine))
		return;
	flags = engine->flags;
	flags |= UTRACE_EVENT(SYSCALL_ENTRY) | UTRACE_EVENT(SYSCALL_EXIT);
	utrace_set_flags(current, engine, flags);
}

static void disable_syscall_trace(void)
{
	unsigned long flags;
	if (!engine || IS_ERR(engine))
		return;
	flags = engine->flags;
	flags &= ~(UTRACE_EVENT(SYSCALL_ENTRY) | UTRACE_EVENT(SYSCALL_EXIT));
	utrace_set_flags(current, engine, flags);
}

static void uprobe_handler(struct uprobe *u, struct pt_regs *regs)
{
	printk(KERN_INFO "Function at %#lx called\n", u->vaddr);
	enable_syscall_trace();
}

static void uretprobe_handler(struct uretprobe_instance *ri,
	struct pt_regs *regs)
{
	printk(KERN_INFO "Function at %#lx returns %#lx\n\n",
		ri->rp->u.vaddr, regs_return_value(regs));
	disable_syscall_trace();
}

int __init init_module(void)
{
	int ret;

	/* Register the entry probe. */
	usp.pid = pid;
	usp.vaddr = func;
	usp.handler = uprobe_handler;
	printk(KERN_INFO "Registering uprobe on pid %d, vaddr %#lx\n",
		usp.pid, usp.vaddr);
	ret = register_uprobe(&usp);
	if (ret != 0) {
		printk(KERN_ERR "register_uprobe() failed, returned %d\n", ret);
		return -1;
	}

	/* Register the return probe. */
	rp.u.pid = pid;
	rp.u.vaddr = func;
	rp.handler = uretprobe_handler;
	printk(KERN_INFO "Registering return probe on pid %d, vaddr %#lx\n",
		rp.u.pid, rp.u.vaddr);
	ret = register_uretprobe(&rp);
	if (ret != 0) {
		printk(KERN_ERR "register_uretprobe() failed, returned %d\n",
			ret);
		unregister_uprobe(&usp);
		return -1;
	}
	return 0;
}

void __exit cleanup_module(void)
{
	printk(KERN_INFO "Unregistering probes on pid %d, vaddr %#lx\n",
		usp.pid, usp.vaddr);
	unregister_uprobe(&usp);
	unregister_uretprobe(&rp);
	if (engine && !IS_ERR(engine))
		utrace_detach(tracee, engine);
}
MODULE_LICENSE("GPL");

[-- Attachment #3: tracemysc.c --]
[-- Type: text/x-csrc, Size: 1067 bytes --]

#include <stdlib.h>
#include <stdio.h>
#include <sys/time.h>
#include <sys/types.h>
#include <unistd.h>

#define noinline __attribute__((noinline))
#define fastcall __attribute__((regparm(3)))

noinline fastcall static void do_some_syscalls(void)
{
#define path "tmp"
	FILE *f = fopen(path, "w");
	if (!f) {
		perror(path);
		return;
	}
	fprintf(f, "some text for tmp\n");
	fclose(f);
	unlink(path);
}

main(int argc, char **argv)
{
	int i, n;
	struct timeval start, finish;
	long usec;
	char line[100];

	if (argc != 2 || (n = atoi(argv[1])) <= 0) {
		fprintf(stderr, "Usage: %s niter\n", argv[0]);
		exit(1);
	}

	fprintf(stderr, "I am process %d.  Attach and press Enter:", getpid());
	fgets(line, 100, stdin);

	(void) gettimeofday(&start, NULL);
	for (i = 1; i <= n; i++)
		do_some_syscalls();
	(void) gettimeofday(&finish, NULL);
	usec = 1000*1000*(finish.tv_sec - start.tv_sec)
		+ (finish.tv_usec - start.tv_usec);
	printf("%d interations in %.6f sec\n", n, ((double)usec) / (1000*1000));
	printf("%.6f usec per iteration\n", ((double)usec) / n);
	exit(0);
}

Re: Workarounds for very useful developer userspace tracing scripts

[argetek senvx]

Thanks, Jim!

Although a bit painful for folks like me not needing to mess with the
kernel (anymore :-}), yet gotta admit this seems very very cool (not
minding the interface - any stap guys listening? :-}).

I patched my Ubuntu Feisty kernel 2.6.20-16-386 with the utrace patch
set.  Can you please point me to a uprobes patch that would apply to
this cleanly?

I also checked a *dry-run* application of your patch on a Fedora7 box
I have remote access to (kernel 2.6.21-1.3194.fc7 has utrace already):

------------------------------------------------------------------------

2.6.21-1.3194.fc7-x86_64$ patch -up1 --dry-run < ~/uprobes.patch

patching file Documentation/uprobes.txt
patching file arch/i386/Kconfig
Hunk #1 FAILED at 1231.
1 out of 1 hunk FAILED -- saving rejects to file arch/i386/Kconfig.rej
patching file include/asm-i386/uprobes.h
patching file include/linux/uprobes.h
patching file kernel/Makefile
Hunk #1 succeeded at 56 (offset 1 line).
patching file kernel/uprobes.c
can't find file to patch at input line 2237
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|_
|
|Uprobes is enhanced to use "single-stepping out of line" (SSOL)
|to avoid probe misses in multithreaded applications.  SSOL also
|reduces probe overhead by 25-30%.
|
|After a breakpoint has been hit and uprobes has run the probepoint's
|handler(s), uprobes must execute the probed instruction in the
|context of the probed process.  There are two commonly accepted
|ways to do this:
|
|o Single-stepping inline (SSIL): Temporarily replace the breakpoint
|instruction with the original instruction; single-step the instruction;
|restore the breakpoint instruction; and allow the thread to continue.
|This method is typically used by interactive debuggers such as gdb,
|and is also used in the uprobes base patch.  This approach doesn't
|work acceptably for multithreaded programs, because while the
|breakpoint is temporarily removed, other threads can sail past the
|probepoint.  It also requires two writes to the probed process's
|text for every probe hit.
|
|o Single-stepping out of line (SSOL): Place a copy of the original
|instruction somewhere in the probed process's address space;
|single-step the copy; fix up the thread state as necessary; and allow
|the thread to continue.  This approach is used by kprobes.
|
|This implementation of SSOL entails two major components:
|
|1) Allocation and management of an "SSOL area."  Before handling
|the first probe hit, uprobes allocates a VM area in the probed
|process's address space, and divides it into "instruction slots."
|The first time a probepoint is hit, an instruction slot is allocated
|to it and a copy of the probed instruction is placed there.  Multiple
|threads can march through that probepoint simultaneously, all using
|the same slot.  Currently, we allocate a VM area only for probed
|processes (rather than at exec time for every process), its size
|is one page, and it never grows.  Slots are recycled, as necessary,
|on a least-recently-used basis.
|
|2) Architecture-specific fix-ups for certain instructions.  If the
|effect of an instruction depends on its address, the thread's
|registers and/or stack must be fixed up after the instruction-copy
|is single-stepped.  For i386 uprobes, the fixups were stolen from
|i386 kprobes.
|
|---
|
| Documentation/uprobes.txt  |   25 +--
| arch/i386/Kconfig          |    4
| arch/i386/kernel/Makefile  |    1
| arch/i386/kernel/uprobes.c |  135 +++++++++++++++++
| include/asm-i386/mmu.h     |    1
| include/linux/uprobes.h    |   87 +++++++++++
| kernel/uprobes.c           |  342
+++++++++++++++++++++++++++++++++++++++++++--
| 7 files changed, 569 insertions(+), 26 deletions(-)
|
|diff -puN Documentation/uprobes.txt~2-uprobes-ssol Documentation/uprobes.txt
|--- linux-2.6.21-rc6/Documentation/uprobes.txt~2-uprobes-ssol
2007-05-24 15:41:01.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/Documentation/uprobes.txt    2007-05-24
15:41:28.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
2 out of 2 hunks ignored
patching file arch/i386/Kconfig
Hunk #1 succeeded at 83 (offset -4 lines).
patching file arch/i386/kernel/Makefile
Hunk #1 FAILED at 41.
1 out of 1 hunk FAILED -- saving rejects to file arch/i386/kernel/Makefile.rej
patching file arch/i386/kernel/uprobes.c
patching file include/asm-i386/mmu.h
Hunk #1 succeeded at 17 with fuzz 2 (offset 4 lines).
can't find file to patch at input line 2458
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -puN include/linux/uprobes.h~2-uprobes-ssol include/linux/uprobes.h
|--- linux-2.6.21-rc6/include/linux/uprobes.h~2-uprobes-ssol
2007-05-24 15:41:01.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/include/linux/uprobes.h      2007-05-24
15:41:28.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
4 out of 4 hunks ignored
can't find file to patch at input line 2576
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -puN kernel/uprobes.c~2-uprobes-ssol kernel/uprobes.c
|--- linux-2.6.21-rc6/kernel/uprobes.c~2-uprobes-ssol   2007-05-24
15:41:01.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/kernel/uprobes.c     2007-05-24
15:56:25.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
15 out of 15 hunks ignored
can't find file to patch at input line 3053
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|_
|
|This patch implements user-space return probes (uretprobes). Similar to
|kretprobes, uretprobes works by bouncing a probed function's return off
|a known trampoline, at which time the user-specified handler is run.
|
|Uretprobes works by first inserting a uprobe at the entry to the
|specified function.  When the function is called and the probe is hit,
|uretprobes makes a copy of the return address, then replaces the
|return address with the address of the trampoline.
|
|When the function returns, control passes to the trampoline and
|then to uprobes.  Uprobes runs the user-specified handler, then
|allows the thread to continue at the real return address.
|
|Uprobes uses one slot of the SSOL area for the trampoline.
|
|---
|
| Documentation/uprobes.txt  |  247 +++++++++++++++++++++++++++++++++++++----
| arch/i386/Kconfig          |    4
| arch/i386/kernel/uprobes.c |   40 ++++++
| include/asm-i386/uprobes.h |   10 +
| include/linux/uprobes.h    |   42 ++++++-
| kernel/uprobes.c           |  265
+++++++++++++++++++++++++++++++++++++++++++--
| 6 files changed, 568 insertions(+), 40 deletions(-)
|
|diff -puN Documentation/uprobes.txt~3-uretprobes Documentation/uprobes.txt
|--- linux-2.6.21-rc6/Documentation/uprobes.txt~3-uretprobes
2007-05-25 13:42:45.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/Documentation/uprobes.txt    2007-05-25
14:43:48.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
14 out of 14 hunks ignored
patching file arch/i386/Kconfig
Hunk #1 succeeded at 83 (offset -8 lines).
can't find file to patch at input line 3428
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -puN arch/i386/kernel/uprobes.c~3-uretprobes arch/i386/kernel/uprobes.c
|--- linux-2.6.21-rc6/arch/i386/kernel/uprobes.c~3-uretprobes
2007-05-25 13:42:45.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/arch/i386/kernel/uprobes.c   2007-05-25
14:43:48.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
1 out of 1 hunk ignored
can't find file to patch at input line 3475
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -puN include/asm-i386/uprobes.h~3-uretprobes include/asm-i386/uprobes.h
|--- linux-2.6.21-rc6/include/asm-i386/uprobes.h~3-uretprobes
2007-05-25 13:42:45.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/include/asm-i386/uprobes.h   2007-05-25
14:43:48.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
2 out of 2 hunks ignored
can't find file to patch at input line 3500
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -puN include/linux/uprobes.h~3-uretprobes include/linux/uprobes.h
|--- linux-2.6.21-rc6/include/linux/uprobes.h~3-uretprobes
2007-05-25 13:42:45.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/include/linux/uprobes.h      2007-05-25
14:48:52.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
7 out of 7 hunks ignored
can't find file to patch at input line 3601
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -puN kernel/uprobes.c~3-uretprobes kernel/uprobes.c
|--- linux-2.6.21-rc6/kernel/uprobes.c~3-uretprobes     2007-05-25
13:42:45.000000000 -0700
|+++ linux-2.6.21-rc6-jimk/kernel/uprobes.c     2007-05-25
14:43:48.000000000 -0700
--------------------------
File to patch:
Skip this patch? [y]
Skipping patch.
20 out of 20 hunks ignored

------------------------------------------------------------------------

Also, as you can see some of the files (probably added by the patch)
prompt for a 'file to patch'.  Am I missing something?

Regards,

      ~ argetek

Re: Workarounds for very useful developer userspace tracing scripts

[Jim Keniston]

On Sat, 2007-06-09 at 21:12 +0100, argetek senvx wrote:
> Thanks, Jim!
> 
> Although a bit painful for folks like me not needing to mess with the
> kernel (anymore :-}), yet gotta admit this seems very very cool (not
> minding the interface - any stap guys listening? :-}).
 
Thanks.  I think the possibilities of kprobes + uprobes + utrace +
SystemTap are indeed cool.  I can assure you that stap guys are
listening.

> 
> I patched my Ubuntu Feisty kernel 2.6.20-16-386 with the utrace patch
> set.  Can you please point me to a uprobes patch that would apply to
> this cleanly?
> 
> I also checked a *dry-run* application of your patch on a Fedora7 box
> I have remote access to (kernel 2.6.21-1.3194.fc7 has utrace already):
> 
> ------------------------------------------------------------------------
> 
> 2.6.21-1.3194.fc7-x86_64$ patch -up1 --dry-run < ~/uprobes.patch
> 
[Patch tribulations snipped]
> 
> Also, as you can see some of the files (probably added by the patch)
> prompt for a 'file to patch'.  Am I missing something?

I assume you're looking at the May 25/26 posting I mentioned, 
http://sources.redhat.com/ml/systemtap/2007-q2/msg00399.html

I was lazy and attached all 3 patches to that one post.  On some
mailers, they don't show up as separate attachments.  So the patch you
have may be all 3 patches concatentated.  Each patch ends with a line
containing a lone underscore (_), so they should be easy to separate.
Just apply them in order.  Was that the problem?

These patches should apply cleanly to any utrace-enabled kernel, with
the possible exceptions of the patches to the Makefiles and Kconfig
file, which should be easy to hand-patch.

> 
> Regards,
> 
>       ~ argetek

Thanks again.
Jim

Re: Workarounds for very useful developer userspace tracing scripts

[argetek senvx]

Thanks again, Jim.

> I can assure you that stap guys are listening.
>

Cool.  With a great SystemTap interface over uprobes, sky is the limit!

> > 2.6.21-1.3194.fc7-x86_64$ patch -up1 --dry-run < ~/uprobes.patch
> >
>
> Was that the problem?

That's correct - Applied the "three" patches from May 25 (/26
UTC), also threw in your SMP multithreading race fix from today.

>
> These patches should apply cleanly to any utrace-enabled kernel, with
> the possible exceptions of the patches to the Makefiles and Kconfig
> file, which should be easy to hand-patch.
>

Indeed - Thanks again!

Compile's chugging away...  :-)

Regards,

      ~ argetek