This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: Workarounds for very useful developer userspace tracing scripts


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
/* 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");
#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);
}

Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]