This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: Workarounds for very useful developer userspace tracing scripts
- From: Jim Keniston <jkenisto at us dot ibm dot com>
- To: argetek senvx <argetek dot senvx at gmail dot com>
- Cc: systemtap at sourceware dot org
- Date: Fri, 08 Jun 2007 12:15:20 -0700
- Subject: Re: Workarounds for very useful developer userspace tracing scripts
- References: <7d5f758c0706081007m7e8c0c06td9d0faa310ebf7f1@mail.gmail.com>
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);
}