DTrace: digging into exec'd comand line args

Brendan Gregg showed me this trick to get at command line args for commands being exec'ed that are greater than the system 80 char limit. In dtrace trying to output the command args using curpsinfo->pr_psargs hits this limit.

The solution is to catch the exec calls and use the destructive dtrace stop() and system() calls to stop the process if it's hg and dump it's args using the system pargs command.

I also wanted to get the Java executing context for the Hg commands that we where executing from our Mercurial Plugin, which is written in Java. This I could do by catching the process create in dtrace. Catching the exec call and testing for hg, allowed me to ensure that I only tracked hg commands and not other exec'ed commands such as the pargs command.

Here's the one liner:

$ dtrace -x switchrate=10 -wn 'proc:::create/execname == "java"/{jstack(20,8000);} proc:::exec/basename(args[0]) == "hg"/{self->trackhg = 1;} proc:::exec-success/self->trackhg/{stop(); system("pargs %d", pid); system("prun %d", pid); self->trackhg =0;}'

You can do a similar thing using the fork and exec syscall probes if you want, though making sure you don't get into a recursive loop when you fire off the pargs command requires a little care :)

$ dtrace -x switchrate=10 -wn syscall::fork\*:entry'/execname == "java"/{jstack(20,5000); isJava[pid] = 1} syscall::exec\*:return/ !progenyof($pid) && isJava[ppid]/{stop(); system("pargs %d", pid); system("prun %d", pid);}'

Here we again dump the stack, but to track the correct exec's we make sure that this exec's parent is java and it's parent is not dtrace. With pargs it's parent is dtrace so this check prevents any recursion. Note: this one liner would also track other exec's from the Java program in it's current form, not just hg.  

 

I've expanded the one liner below to add timings into the script:

 

#!/usr/sbin/dtrace -ws
/\*
    mercurial_plugin_hgcalls.d
    
    Trace hg calls made from Java application (NetBeans IDE), using pargs to
    get full listing of args to hg call. 
\*/
#pragma D option quiet
#pragma D option switchrate=10

proc:::create
/execname == "java"/
{
    jstack(20,8000);    
}

proc:::exec
/basename(args[0]) == "hg"/
{
    self->track = 1;
    self->startexec = timestamp;
}

proc:::exec-success
/self->track/
{
    this->timeexec = timestamp - (self->startexec > 0 ? self->startexec: 0);
    self->startexec = 0;
    printf("Elasped Start Exec Time: %d msec\\n", (this->timeexec)/1000000);
    @["Total Start Exec Time: (msec) "] = sum(this->timeexec);
    stop(); 
    system("pargs %d", pid); 
    system("prun %d", pid);
    self->start = timestamp;
}

proc:::exit
/self->start/
{
    this->time = timestamp - self->start;
    printf("Elasped Hg Cmd Time: %d msec\\n", (this->time)/1000000);
    @["Total Hg Cmd Time: (msec) "] = sum(this->time);
    self->startexec = 0;
    self->track = 0;
    self->start = 0;
}

proc:::exec-failure
/self->track/
{
    printf("Hg Command failed: errno: %d \\n", args[0]);
    self->startexec = 0;
    self->track = 0;
    self->start = 0;
}

END
{
    normalize(@, 1000000);
}

 




 

Comments:

Post a Comment:
Comments are closed for this entry.
About

jmr

Search

Top Tags
Categories
Archives
« April 2014
MonTueWedThuFriSatSun
 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
    
       
Today