Sunday Oct 24, 2010

New Videos

Some new videos have been posted of myself and others speaking about DTrace and performance, including: Enjoy!

Friday Oct 01, 2010

DTrace materials from Oracle OpenWorld 2010

At Oracle OpenWorld I gave a talk titled How to Build Better Applications With Oracle Solaris DTrace, written by myself and Jim Mauro. Click the link to see the slides, and video is here. Another DTrace talk is online in video form: a chat with Rick Ramsey about DTrace for system administrators. Enjoy!

Wednesday Sep 22, 2010

DTrace book coming soon

Jim Mauro and I recently handed the manuscript for the DTrace book to the publisher, which (unformatted) came in at over 900 pages. It covers using DTrace, complementary to the DTrace Guide, and should serve as a cookbook of DTrace scripts and one-liners for topics spanning the entire software stack. It also contains strategies and checklists for these topics, to help the reader develop scripts further.

The chapters are:

  1. Introduction
  2. The D Language
  3. System View
  4. Disk I/O
  5. Filesystems
  6. Network Lower Level Protocols
  7. Application Level Protocols
  8. Languages
  9. Applications
  10. Databases
  11. Security
  12. Kernel
  13. Tools
  14. Tips and Tricks

The book contains over 230 DTrace scripts and over 270 one-liners, many of which are new, and go much further than I have done previously in the DTraceToolkit.

Our intent was ambitious: this wasn't to be just a cookbook of scripts, but a cookbook of useful scripts and strategy that spanned the entire software stack - covering both easy and difficult topics alike. We wrote up the chapters and subtopics that such a book would ideally cover, and then created the content - much of which didn't exist before.

It's taken most of the past year to develop and write this material - consuming all of my spare time at the expense of many things: blog entries, DTraceToolkit updates, and other personal sacrifices. It's been exhausting at times, but it's also very satisfying to have finally completed. The publisher is now turning this into the finished product, a process which typically takes a few months.

Thursday Nov 05, 2009

DTrace Cheatsheet

A while ago Jonathan Adams posted an mdb cheatsheet, summarizing the syntax and commands of the Solaris Modular Debugger. It's a pretty handy reference, and last week I used it as a handout when teaching a class that included both mdb and DTrace. Well, I have the mdb cheatsheet - what about a DTrace one?

Here is my DTrace cheatsheet, styled by Todd. This doesn't include all of DTrace - it includes what I use most frequently. As a reminder, I flicked through the DTraceToolkit to see what I frequently used in those scripts.

If you learn what everything does on that one page cheatsheet including the one-liners, you'll know a significant amount of DTrace. If something has been summarized too much on that cheatsheet, refer to the full DTrace Guide.

Sunday Feb 17, 2008

DTrace Links

A few happenings in the increasingly busy world of DTrace:

Friday Aug 10, 2007

DTrace Bourne shell (sh) provider

Alan Hargreaves has prototyped a DTrace Bourne shell provider, and is looking ahead to see how this can be integrated with Solaris and OpenSolaris. This is great news for anyone who would like to analyze or troubleshoot their Bourne shell scripts. It is also good news for people (especially system administrators) wanting to learn DTrace, as it may provide a familiar path (sh scripting) for you to learn user-land DTracing.

Why sh, and not csh, tcsh, ksh, bash or zsh? Alan could have done any, we wanted to start with the Bourne shell to both get it done and as an example for the other shell providers to follow (watch this space). So if you really just care about bash or whatever, then learning about the sh provider now should be a useful heads-up of what should be possible.

hello.sh

When learning to DTrace software, it can be best to start with the simple stuff. Confirm that what you think will happen, does indeed happen, then move to progressivly more complex scripts.

Here is hello.sh, a dead simple script to start with,

    # cat -n hello.sh   
         1  #!./sh
         2
         3  echo "Hello World!"
         4  echo "Hello World!"
         5  echo "Hello World!"
         6  echo "Hello World!"
         7  echo "Hello World!"   
    
The following DTrace one-liner will run hello.sh (-c), trace all sh provider probes (sh\*:::), and frequency count their probe names (@[probename] = count()).

    # dtrace -Zn 'sh$target::: { @[probename] = count(); }' -c ./hello.sh   
    dtrace: description 'sh$target::: ' matched 9 probes
    Hello World!
    Hello World!
    Hello World!
    Hello World!
    Hello World!
    dtrace: pid 248847 has exited
    
      script-begin                                                      1
      script-end                                                        1
      builtin-entry                                                     5
      builtin-return                                                    5
      line                                                              5
    
So builtin-entry and builtin-return were called 5 times, one for each echo. The line probe was also called 5 times, once for each line that the shell executed.

Frequency counting builtins

Each probe provides useful information in their args, such as the script name, builtin or exec name, line number, etc. Here I'll use the builtin-entry probe to frequency count the builtin names,

    # dtrace -Zn 'sh$target:::builtin-entry { @[copyinstr(arg1)] = count(); }' -c ./hello.sh   
    dtrace: description 'sh$target:::builtin-entry ' matched 1 probe
    Hello World!
    [...]
    dtrace: pid 248851 has exited
    
      echo                                                              5
    
That found that echo was called 5 times. Nothing suprising there, this is just confirming that the probes behave as they should.

Line number tracing

The line probe allows us to trace line execution. This one liner counts how many times each line was run,

    # dtrace -Zn 'sh$target:::line { @[arg1] = count(); }' -c ./hello.sh   
    dtrace: description 'sh$target:::line ' matched 1 probe
    Hello World!
    [...]
    dtrace: pid 248855 has exited
    
                    3                1
                    4                1
                    5                1
                    6                1
                    7                1
    
Each of the lines 3 to 7 were called once, as expected. This one-liner should be useful for finding loop hotspots.

And the following one-liner traces line execution live,

    # dtrace -Zn 'sh$target:::line { trace(arg1); }' -c ./hello.sh   
    dtrace: description 'sh$target:::line ' matched 1 probe
    Hello World!
    [...]
    CPU     ID                    FUNCTION:NAME
      0  54539                     execute:line                 3
      0  54539                     execute:line                 4
      0  54539                     execute:line                 5
      0  54539                     execute:line                 6
      0  54539                     execute:line                 7
    dtrace: pid 248869 has exited
    
Great, that works. Is this getting too easy? lets move on...

func_abc.sh

Now for somthing a little harder (and more interesting). In the following script, func_a() calls func_b() which calls func_c().

# cat -n func_abc.sh   
     1  #!./sh
     2
     3  func_c()
     4  {
     5          echo "Function C"
     6          sleep 1
     7  }
     8
     9  func_b()
    10  {
    11          echo "Function B"
    12          sleep 1
    13          func_c
    14  }
    15
    16  func_a()
    17  {
    18          echo "Function A"
    19          sleep 1
    20          func_b
    21  }
    22
    23  func_a
What order will the lines be executed now? Try thinking about it before checking the answer below.

Tracing line execution

    # dtrace -Zn 'sh$target:::line { trace(arg1); }' -c ./func_abc.sh 
    dtrace: description 'sh$target:::line ' matched 1 probe
    Function A
    CPU     ID                    FUNCTION:NAME
      0  54539                     execute:line                23
      0  54539                     execute:line                18
      0  54539                     execute:line                19      pause
    Function B
      0  54539                     execute:line                20
      0  54539                     execute:line                11
      0  54539                     execute:line                12      pause
    Function C
      0  54539                     execute:line                13
      0  54539                     execute:line                 5
      0  54539                     execute:line                 6      pause
    dtrace: pid 248873 has exited
    
There were some conspicuous one-second pauses during the output, which are sadly lost in this screen shot. I've added the word "pause" so that you know when that happened.

The order of the lines does make sense. What might be confusing is that we see the output text "Function B" followed by the trace of line 20 -- this is due to DTrace output buffering.

Tracing function flow - sh_flow.d

Since we have function-entry and function-return probes, we can trace function execution and indent the output based on the function depth. The following demonstrates sh_flow.d - a script which does just that for any script running on the system (with this sh provider enabled binary), and also traces builtin calls and command executions. sh_flow.d is run in one window, and func_abc.sh runs in another.

    # ./sh_flow.d   
    C TIME                  FILE                     -- NAME
    0 2007 Aug 10 18:41:10  func_abc.sh              -> func_a
    0 2007 Aug 10 18:41:10  func_abc.sh                 > echo
    0 2007 Aug 10 18:41:10  func_abc.sh                 | sleep
    0 2007 Aug 10 18:41:11  func_abc.sh                -> func_b
    0 2007 Aug 10 18:41:11  func_abc.sh                   > echo
    0 2007 Aug 10 18:41:11  func_abc.sh                   | sleep
    0 2007 Aug 10 18:41:12  func_abc.sh                  -> func_c
    0 2007 Aug 10 18:41:12  func_abc.sh                     > echo
    0 2007 Aug 10 18:41:12  func_abc.sh                     | sleep
    0 2007 Aug 10 18:41:13  func_abc.sh                  <- func_c
    0 2007 Aug 10 18:41:13  func_abc.sh                <- func_b
    0 2007 Aug 10 18:41:13  func_abc.sh              <- func_a
    \^C
    
The legend is,

    ->function entry
    <-function return
    >builtin entry
    |command entry
Great! the output makes it clear who is calling who.

The sh_flow.d script is,

    #!/usr/sbin/dtrace -Zs
    /\*
     \* sh_flow.d - snoop Bourne shell execution showing function flow.
     \*             Written for the Solaris sh DTrace provider.
     \*
     \* This traces shell activity from all Bourne shells on the system that are
     \* running with sh provider support.
     \*
     \* USAGE: sh_flow.d                     # hit Ctrl-C to end
     \*
     \* This watches shell function entries and returns, and indents child
     \* function calls. Shell builtins are also printed.
     \*
     \* FIELDS:
     \*              C               CPU-id
     \*              TIME            Time of execution
     \*              FILE            Filename that this function belongs to
     \*              NAME            Shell function, builtin or command name
     \*
     \* If a name isn't available at the time of tracing, "<null>" is printed.
     \*
     \* WARNING: Watch the first column carefully, it prints the CPU-id. If it
     \* changes, then it is very likely that the output has been shuffled.
     \*/
    
    #pragma D option quiet
    #pragma D option switchrate=10
    
    dtrace:::BEGIN
    {
            depth = 0;
            printf("%s %-20s  %-22s   -- %s\\n", "C", "TIME", "FILE", "NAME");
    }
    
    sh\*:::function-entry
    {
            depth++;
            printf("%d %-20Y  %-22s %\*s-> %s\\n", cpu, walltimestamp, 
                basename(copyinstr(arg0)), depth\*2, "", copyinstr(arg1));
    }
    
    sh\*:::function-return
    {
            printf("%d %-20Y  %-22s %\*s<- %s\\n", cpu, walltimestamp,
                basename(copyinstr(arg0)), depth\*2, "", copyinstr(arg1));
            depth--;
    }
    
    sh\*:::builtin-entry
    {
            printf("%d %-20Y  %-22s %\*s   > %s\\n", cpu, walltimestamp, 
                basename(copyinstr(arg0)), depth\*2, "", copyinstr(arg1));
    }
    
    sh\*:::command-entry
    {
            printf("%d %-20Y  %-22s %\*s   | %s\\n", cpu, walltimestamp, 
                basename(copyinstr(arg0)), depth\*2, "", copyinstr(arg1));
    }
    
Tracing function flow with times - sh_flowtime.d

A great feature of DTrace is the availability of high resolution timestamps. Here I've enhanced the previous script to print delta times,

    # ./sh_flowtime.d
    C TIME                  FILE                 DELTA(us)  -- NAME
    0 2007 Aug 10 18:52:51  func_abc.sh                  0   -> func_a
    0 2007 Aug 10 18:52:51  func_abc.sh                 54      > echo
    0 2007 Aug 10 18:52:52  func_abc.sh            1022880      | sleep
    0 2007 Aug 10 18:52:52  func_abc.sh                 34     -> func_b
    0 2007 Aug 10 18:52:52  func_abc.sh                 44        > echo
    0 2007 Aug 10 18:52:53  func_abc.sh            1029963        | sleep
    0 2007 Aug 10 18:52:53  func_abc.sh                 44       -> func_c
    0 2007 Aug 10 18:52:53  func_abc.sh                 43          > echo
    0 2007 Aug 10 18:52:54  func_abc.sh            1029863          | sleep
    0 2007 Aug 10 18:52:54  func_abc.sh                 33       <- func_c
    0 2007 Aug 10 18:52:54  func_abc.sh                 14     <- func_b
    0 2007 Aug 10 18:52:54  func_abc.sh                  7   <- func_a
    \^C
    
The legend for understanding the delta times is, The legend is,

    ->function entrytime from the previous event, to the entry of this function
    <-function returntime from the previous event, to the completion of this function
    >builtin entrytime from the previous event, to when this builtin completed execution
    |command entrytime from the previous event, to when this command completed execution
Hey - we found the latency in the script, it's those 1.02 second calls to "sleep"! :-)

Being able to present this information in such a compelling way is awsome stuff.

I won't include the source to that script just yet (this blog entry will get too long), but I'll encourage Alan to bundle these scripts along with the patch/binary of the sh provider (when he makes that available).

Tracing type times - sh_typetime.d

If your script is rather long, the above output from sh_flowtime.d may get rather long. This condensed summary may be more practical,

    # ./sh_typetime.d
    Tracing... Hit Ctrl-C to end.
    \^C
     FILE                             TYPE     NAME                   TIME(us)
     func_abc.sh                      builtin  echo                         82
     func_abc.sh                      func     func_c                      260
     func_abc.sh                      func     func_b                      285
     func_abc.sh                      func     func_a                      478
     func_abc.sh                      exec     sleep                   3080418
    
It's pretty obvious from that output where the time was spent.

I was experimenting with more exciting forms of that type of script,

    # ./sh_typetime2.d   
    Tracing... Hit Ctrl-C to end.
    \^C
     FILE               TYPE     NAME                    COUNT  ELAPSED   ON-CPU
     func_abc.sh        func     func_c                      1      296       31
     func_abc.sh        func     func_b                      1      346       44
     func_abc.sh        func     func_a                      1      529       61
     func_abc.sh        builtin  echo                        3       87       77
     func_abc.sh        exec     sleep                       3  3085831    53984
    
Lots more will be possible - Alan only wrote the provider two days ago, so I haven't had much of a chance to write scripts yet!

Real world tracing

Alan literally wrote this provider from scratch in the last few days, so we haven't had a chance to point it at something big yet. Here's at least one example of something familiar, /etc/profile,

    # ./sh_typetime2.d
    Tracing... Hit Ctrl-C to end.
    \^C
     FILE               TYPE     NAME                    COUNT  ELAPSED   ON-CPU
     profile            builtin  [                           1        3        2
     profile            builtin  umask                       1        4        3
     profile            builtin  export                      1        5        3
     profile            builtin  trap                        2       30       22
    
Cool. See Alan's blog for updates.

Tuesday Jul 31, 2007

iSCSI DTrace provider

I recently tried out the new iSCSI Target Server DTrace provider which Adam wrote (which should be included in Solaris sometime soon). It provides observability of iSCSI traffic from the the server's perspective. This is great news if you have an iSCSI Solaris server, or are planning to have one.

In this entry I'll post a few screenshots of the iSCSI provider in action, both one-liners and scripts.

one-liners

I'll start by listing the probes - which may convey a sense of what is possible to trace. Look down the "NAME" column,
# dtrace -ln 'iscsi\*:::'
   ID    PROVIDER            MODULE                          FUNCTION NAME
11696 iscsi100653         iscsitgtd                 send_async_logout async-send
11697 iscsi100653         iscsitgtd                   send_async_scsi async-send
11698 iscsi100653         iscsitgtd                  handle_scsi_data data-receive
11699 iscsi100653         iscsitgtd              iscsi_conn_data_rqst data-request
11700 iscsi100653         iscsitgtd                   send_datain_pdu data-send
11701 iscsi100653         iscsitgtd            iscsi_handle_login_pkt login-command
11702 iscsi100653         iscsitgtd                 send_login_reject login-response
11703 iscsi100653         iscsitgtd            iscsi_handle_login_pkt login-response
11704 iscsi100653         iscsitgtd                 handle_logout_msg logout-command
11705 iscsi100653         iscsitgtd                        conn_state logout-response
11706 iscsi100653         iscsitgtd                   handle_noop_cmd nop-receive
11707 iscsi100653         iscsitgtd                    iscsi_conn_pkt nop-send
11708 iscsi100653         iscsitgtd                   handle_scsi_cmd scsi-command
11709 iscsi100653         iscsitgtd                     send_scsi_rsp scsi-response
11710 iscsi100653         iscsitgtd                   handle_task_mgt task-command
11711 iscsi100653         iscsitgtd                    iscsi_conn_pkt task-response
11712 iscsi100653         iscsitgtd                   handle_text_msg text-command
11713 iscsi100653         iscsitgtd                   handle_text_msg text-response
The easiest one-liner would be to frequency count iSCSI operations,
# dtrace -n 'iscsi\*::: { @[probename] = count(); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  nop-receive                                                       3
  nop-send                                                          3
  data-receive                                                     55
  data-request                                                     55
  scsi-response                                                   103
  scsi-command                                                    342
  data-send                                                      2865
The above output shows that the iSCSI server is doing more send operations (2865 data-sends), than receive (55 data-receives).

Now to see who is using this iSCSI server, by frequency counting remote IP addresses,

# dtrace -n 'iscsi\*::: { @[args[0]->ci_remote] = count(); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  192.168.1.109                                                  1338
The above shows that 192.168.1.108 triggered 1338 iSCSI operations - which may have been sends, receives, nops, etc. Breaking down further is just a little more DTrace,
# dtrace -qn 'iscsi\*::: { @[args[0]->ci_remote, probename] = count(); } 
  END { printa("%32s %18s %@16d\\n", @); }'
\^C
                   192.168.1.109        nop-receive                2
                   192.168.1.109           nop-send                2
                   192.168.1.109       data-receive               16
                   192.168.1.109       data-request               16
                   192.168.1.109      scsi-response               43
                   192.168.1.109       scsi-command              253
                   192.168.1.109          data-send             2619
Great, while a simple one-liner - it quickly identifies who is connecting and what operations they are doing. Some performance wins are about locating and eliminating unnecessary work, which one-liners such as this help identify.

Now for printing payload bytes by iSCSI operation,

# dtrace -n 'iscsi\*::: { @[probename] = sum(args[1]->ii_datalen); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  data-request                                                      0
  scsi-response                                                     0
  data-receive                                                  99328
  scsi-command                                                 140800
  data-send                                                  20672512
The above one-liner prints total bytes by operation, which does lose some data - what was the count by operation, average, min, max? DTrace can answer all of these seperately, or provide a summary as a distribution plot. Here I've used quantize for a power of 2 plot,
# dtrace -n 'iscsi\*::: { @[probename] = quantize(args[2]->ii_datalen); }'
dtrace: description 'iscsi\*::: ' matched 18 probes
\^C

  data-request                                      
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12       
               1 |                                         0        

  scsi-response                                     
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 55       
               1 |                                         0        

  data-receive                                      
           value  ------------- Distribution ------------- count    
             512 |                                         0        
            1024 |@@@@@@@                                  2        
            2048 |                                         0        
            4096 |@@@@@@@@@@@@@                            4        
            8192 |@@@@@@@@@@@@@@@@@@@@                     6        
           16384 |                                         0        

  scsi-command                                      
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         209      
               1 |                                         0        
               2 |                                         0        
               4 |                                         0        
               8 |                                         0        
              16 |                                         0        
              32 |                                         0        
              64 |                                         0        
             128 |                                         0        
             256 |                                         0        
             512 |@@@                                      18       
            1024 |@@                                       10       
            2048 |@@                                       11       
            4096 |@                                        4        
            8192 |@@                                       12       
           16384 |                                         0        

  data-send                                         
           value  ------------- Distribution ------------- count    
             256 |                                         0        
             512 |                                         1        
            1024 |                                         16       
            2048 |                                         21       
            4096 |                                         28       
            8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  2559     
           16384 |                                         0        
The plots above show that for the data-send operation, the payload size was usually in the 8 to 16 Kbyte bucket.

scripts

Apart from one-lines, DTrace allows powerful scripts to be contstructed. I've put a few on the SolarisInternals DTrace Topics: iSCSI page.

Here I'll post my favourite so far - a script which measures read/write latency (or "response time") in nanoseconds,

# ./iscsirwlat.d 
Tracing... Hit Ctrl-C to end.
\^C
Read Latency (ns),

  192.168.1.109                                     
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |@@@                                      27       
          131072 |@@                                       17       
          262144 |                                         4        
          524288 |@@@@                                     39       
         1048576 |@@@                                      32       
         2097152 |@@@@@@@@@@@@@@@@@                        164      
         4194304 |@                                        11       
         8388608 |@                                        5        
        16777216 |@                                        10       
        33554432 |@                                        7        
        67108864 |@                                        5        
       134217728 |@@@@@                                    46       
       268435456 |@                                        14       
       536870912 |                                         0        

Write Latency (ns),

  192.168.1.109                                     
           value  ------------- Distribution ------------- count    
           32768 |                                         0        
           65536 |@@                                       14       
          131072 |@@                                       16       
          262144 |@@@                                      20       
          524288 |@@@                                      20       
         1048576 |@@@@@                                    33       
         2097152 |@                                        5        
         4194304 |                                         0        
         8388608 |                                         2        
        16777216 |@                                        10       
        33554432 |@@@                                      18       
        67108864 |@@@@@                                    33       
       134217728 |@@@@@@@@@@@@@                            93       
       268435456 |@@                                       12       
       536870912 |                                         0        
The script is on the DTrace Topics page. It is a glimpse of things to come; how many of those were synchronous requests (which may hurt application performance) versus asynchronous flushing or read ahead (which may not hurt performance)? More DTrace is needed - which will probably include running DTrace on the client side as well...

Monday Jul 30, 2007

JavaScript DTrace provider ver 2.0

About 2 months ago I posted an update to the JavaScript DTrace provider to Bugzilla. In case you are interested and missed it, here are some details: The new additions were,

  • the ability to identify anonymous functions (js_function-info)
  • access to function entry arguments (js_function-args)
  • access to function return value (js_function-rval)
I was finding that the JavaScript provider was only helping with about 4 problems out of 10 (still, better than nothing). The improvements that I added should take that to around 8 out of 10 - so it is now proving to be really useful.

Anyhow, here are some before and after screenshots, tracing a simple JavaScript clock (it's enough to demonstrate the features without bogging down in application specifics),

Old,

# ./js_funcflow.d
C TIME                  FILE                     -- FUNC
1 2007 May 31 06:07:13  clock2.html              -> startTime
1 2007 May 31 06:07:13  clock2.html                -> getHours
1 2007 May 31 06:07:13  clock2.html                <- getHours
1 2007 May 31 06:07:13  clocklib.js                -> padLibZero
1 2007 May 31 06:07:13  clocklib.js                <- padLibZero
1 2007 May 31 06:07:13  clock2.html                -> getMinutes
1 2007 May 31 06:07:13  clock2.html                <- getMinutes
1 2007 May 31 06:07:13  clocklib.js                -> padLibZero
1 2007 May 31 06:07:13  clocklib.js                <- padLibZero
1 2007 May 31 06:07:13  clock2.html                -> getSeconds
1 2007 May 31 06:07:13  clock2.html                <- getSeconds
1 2007 May 31 06:07:13  clocklib.js                -> padLibZero
1 2007 May 31 06:07:13  clocklib.js                <- padLibZero
1 2007 May 31 06:07:13  clock2.html                -> getElementById
1 2007 May 31 06:07:13  clock2.html                <- getElementById
1 2007 May 31 06:07:13  clock2.html                -> setTimeout
1 2007 May 31 06:07:13  clock2.html                <- setTimeout
1 2007 May 31 06:07:13  clock2.html              <- startTime
\^C
New,
# ./js_argflow.d
C TIME                  FILE                 -- FUNC()
1 2007 May 31 06:07:34  clock2.html           -> startTime()
1 2007 May 31 06:07:34  clock2.html             -> getHours()
1 2007 May 31 06:07:34  clock2.html             <- startTime:9 = 0x80000000
1 2007 May 31 06:07:34  clocklib.js             -> padLibZero(0x6)
1 2007 May 31 06:07:34  clocklib.js             <- padLibZero:3 = 0x955fd70
1 2007 May 31 06:07:34  clock2.html             -> getMinutes()
1 2007 May 31 06:07:34  clock2.html             <- startTime:10 = 0x80000000
1 2007 May 31 06:07:34  clocklib.js             -> padLibZero(0x7)
1 2007 May 31 06:07:34  clocklib.js             <- padLibZero:3 = 0x955fd50
1 2007 May 31 06:07:34  clock2.html             -> getSeconds()
1 2007 May 31 06:07:34  clock2.html             <- startTime:11 = 0x80000000
1 2007 May 31 06:07:34  clocklib.js             -> padLibZero(0x22)
1 2007 May 31 06:07:34  clocklib.js             <- padLibZero:4 = 0x22
1 2007 May 31 06:07:34  clock2.html             -> getElementById()
1 2007 May 31 06:07:34  clock2.html             <- startTime:12 = 0x80000000
1 2007 May 31 06:07:34  clock2.html             -> setTimeout()
1 2007 May 31 06:07:34  clock2.html             <- startTime:13 = 0x80000000
1 2007 May 31 06:07:34  clock2.html           <- startTime:13 = 0x80000000
\^C
Now there is some visibility for function arguments and return values. If arguments are strings, it is possible to print them as such from DTrace.

Old,

# ./js_funccalls.d
Tracing... Hit Ctrl-C to end.
\^C
 FILE                             FUNC                                    CALLS
 clock2.html                      getElementById                              1
 clock2.html                      getHours                                    1
 clock2.html                      getMinutes                                  1
 clock2.html                      getSeconds                                  1
 clock2.html                      setTimeout                                  1
 clock2.html                      startTime                                   1
 clocklib.js                      padLibZero                                  3
New,
# ./js_funcinfo.d
Tracing... Hit Ctrl-C to end.
\^C
 BASE[FILE:LINE]         FUNCNAME             RUN[FILE:LINE]             CALLS
 clock2.html:7           getElementById       clock2.html:12                 1
 clock2.html:7           getHours             clock2.html:9                  1
 clock2.html:7           getMinutes           clock2.html:10                 1
 clock2.html:7           getSeconds           clock2.html:11                 1
 clock2.html:7           setTimeout           clock2.html:13                 1
 clock2.html:7           startTime            clock2.html:13                 1
 clocklib.js:2           padLibZero           clock2.html:10                 1
 clocklib.js:2           padLibZero           clock2.html:11                 1
 clocklib.js:2           padLibZero           clock2.html:9                  1
The "BASE" info describes where that function was declared or first referred to; the "RUN" info describes where that function was executed. These details are especially useful for tracing anonymous functions.

The scripts used above can be downloaded in a tar file from the OpenSolaris DTrace JavaScript site.

There are a number of people at Sun and at Mozilla helping to put DTrace probes in Mozilla, not just for JavaScript - but also for tracing browser latencies at a level which is useful for developers. For more information see the OpenSolaris page, and on Bugzilla: 370906, 388564.

About

Brendan Gregg, Fishworks engineer

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
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