Skip to content

Commit

Permalink
Revives the libunwind work to allow "mixed-mode" R and C profiling.
Browse files Browse the repository at this point in the history
This takes a different approach than the original, only including the
native C/C++ stack *above* the last R frame -- inspired by the py-spy
project.

Partly, this concession is because merging the stacks reliably turns out
to be quite difficult, particularly due to R's lazy evaluation. But it
also reflects more closely what I think users are actually looking for
in such joint profiles.

Progress towards #8.
  • Loading branch information
atheriel committed Mar 17, 2020
1 parent 843d197 commit 18996eb
Show file tree
Hide file tree
Showing 3 changed files with 93 additions and 4 deletions.
2 changes: 1 addition & 1 deletion Makefile
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
CFLAGS = -O2 -Wall -fPIC -g
LIBS = -lelf
LIBS = -lelf -lunwind-ptrace -lunwind-generic

BIN = xrprof
BINOBJ = src/xrprof.o
Expand Down
5 changes: 5 additions & 0 deletions docs/xrprof.1
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ xrprof \- profile R programs
.SH SYNOPSIS
.B xrprof
.RB [ -h ]
.RB [ -m ]
.RB [ -F
.IR FREQ ]
.RB [ -d
Expand Down Expand Up @@ -37,6 +38,10 @@ Set the duration for
.B xrprof
to take samples before exiting (provided the target program runs that
long). The default is to last up to one hour.
.TP
.B \-m
Run in \*(lqmixed mode\*(rq, where samples are drawn from both the
R-level and native C/C++ stacks and collated together.
.SH EXAMPLES
Sample from an existing R program for 5 seconds at a useful frequency:
.PP
Expand Down
90 changes: 87 additions & 3 deletions src/xrprof.c
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,8 @@
#include <sys/wait.h>
#include <time.h> /* for timespec */

#include <libunwind-ptrace.h>

#include "cursor.h"

#define MAX_STACK_DEPTH 100
Expand All @@ -26,18 +28,18 @@ void handle_sigint(int _sig) {

void usage(const char *name) {
// TODO: Add a long help message.
printf("Usage: %s [-v] [-F <freq>] [-d <duration>] -p <pid>\n", name);
printf("Usage: %s [-v] [-m] [-F <freq>] [-d <duration>] -p <pid>\n", name);
return;
}

int main(int argc, char **argv) {
pid_t pid = -1;
int freq = DEFAULT_FREQ;
float duration = DEFAULT_DURATION;
int verbose = 0;
int verbose = 0, mixed_mode = 0;

int opt;
while ((opt = getopt(argc, argv, "hvF:d:p:")) != -1) {
while ((opt = getopt(argc, argv, "hvmF:d:p:")) != -1) {
switch (opt) {
case 'h':
usage(argv[0]);
Expand All @@ -46,6 +48,9 @@ int main(int argc, char **argv) {
case 'v':
verbose++;
break;
case 'm':
mixed_mode = 1;
break;
case 'p':
pid = strtol(optarg, NULL, 10);
if ((errno == ERANGE && (pid == LONG_MAX || pid == LONG_MIN)) ||
Expand Down Expand Up @@ -114,6 +119,15 @@ int main(int argc, char **argv) {
goto done;
}

unw_addr_space_t uw_as;
void *uw_cxt;
unw_cursor_t uw_cursor;
if (mixed_mode) {
uw_as = unw_create_addr_space(&_UPT_accessors, 0);
unw_set_caching_policy(uw_as, UNW_CACHE_GLOBAL);
uw_cxt = _UPT_create(pid);
}

/* Stop the tracee and read the R stack information. */

// Allow the user to stop the tracing with Ctrl-C.
Expand Down Expand Up @@ -161,6 +175,76 @@ int main(int argc, char **argv) {
goto done;
}

if (mixed_mode && unw_init_remote(&uw_cursor, uw_as, uw_cxt) != 0) {
perror("fatal: Failed to initialize libunwind cursor.");
code++;
goto done;
} else if (mixed_mode) {
char sym[256];
unw_word_t offset, ip;
unw_proc_info_t info;

do {
sym[0] = '\0';
if ((ret = unw_get_proc_info(&uw_cursor, &info)) < 0) {
code++;
fprintf(stderr, "fatal: Failed to get proc info via libunwind: %d.\n",
ret);
goto done;
}

if ((ret = unw_get_reg(&uw_cursor, UNW_REG_IP, &ip)) < 0) {
code++;
fprintf(stderr, "fatal: Failed to get IP register via libunwind: %d.\n",
ret);
goto done;
}

if ((ret = unw_get_proc_name(&uw_cursor, sym, sizeof(sym), &offset)) < 0) {
if (ret == -UNW_EUNSPEC || ret == -UNW_ENOINFO) {
printf("\"<Native:0x%lx>\" ", ip);
continue;
} else if (ret != -UNW_ENOINFO) {
code++;
fprintf(stderr, "fatal: Failed to get proc symbol via libunwind: %d.\n",
ret);
goto done;
}
/* Symbol is truncated but otherwise fine. */
}

/* We're not actually in the named procedure, but nearby.
TODO: The printed address is wrong; it does not account for ASLR. */
if (ip > info.end_ip) {
printf("\"<Native:0x%lx>\" ", ip);
continue;
}

/* TODO: Not sure what's going on here. */
if (strncmp(sym, "do_Rprof", 8) == 0) {
continue;
}

/* Look for the first eval call and jump into the R stack. */
if (strncmp(sym, "Rf_eval", 7) == 0) {
break;
}

/* Bail if we get to what looks like the REPL loop. */
if (strncmp(sym, "Rf_ReplIteration", 16) == 0) {
break;
}

printf("\"<Native:%s>\" ", sym);
} while ((ret = unw_step(&uw_cursor)) > 0);

if (ret < 0) {
code++;
fprintf(stderr, "fatal: Failed to step libunwind cursor: %d.\n", ret);
goto done;
}
}

do {
rsym[0] = '\0';
if ((ret = xrprof_get_fun_name(cursor, rsym, sizeof(rsym))) < 0) {
Expand Down

0 comments on commit 18996eb

Please # to comment.