End-to-End Tracing of Ajax/Java Applications Using DTrace
|
|
| By Amit Hurvitz, July 2007 |
 |
|
Ajax is an emerging technology, which got a significant boost with the rise of applications like Google Maps. Ajax is increasing the level of interaction between the code running under the browser and the server, thus allowing web applications, like Google Maps, to be more interactive. This higher granularity of communication to the server might make understanding performance issues tougher. Sometimes you need to understand the call flow, and check the time spent in any client JavaScript function and server (probably Java) method. DTrace will help.
DTrace is a Solaris (10 and above) tracing infrastructure with scripting capabilities, which enables high observation capabilities into both system and user activities. It allows probing of almost every system (I/O, network, scheduling, memory) operation, as well as tracing user native and Java programming language code. It also has an easy-to-implement and straightforward mechanism, called USDT, to add user probes to a C program. For basic and advanced information on DTrace, start at the OpenSolaris community DTrace page.
The Mozilla DTrace project at OpenSolaris offers JavaScript tracing capabilities using DTrace. You will need to have the DTrace instumented Firefox in order to trace JavaScript functions with DTrace. In order to use this Mozilla DTrace capability, you will also need to run on a recent Solaris Express build (63 or higher).
Java tracing by DTrace is enabled in Java 1.4.2 and 5.0 by published agents, based on JVMPI/JVMTI. In Java 6.0, DTrace instrumentation is built in the JVM on Solaris, so there is no need to dynamically link with a JVMPI/JVMTI shared library in order to use DTrace probes. Java 6.0 probes are described in detail in Keith McGuigan's weblog. Good examples for using Java probes can be found at Katya's examples.
I am using an Ajax validation example from Sang Shin's excellent Introduction to Ajax course. To run this example, either follow that page's directions, or the quick direction list below.
In my simplistic environment, I run both the browser and the application server (a servlet engine) on the same machine. This allows me to use one DTrace script to trace both, and easily see one combined sequence of JavaScript functions and Java methods. You might DTrace JavaScript on a client machine and DTrace the back-end on another server machine, as long as they both run Solaris (10 and above) for Java (server), Solaris Express build 63 or higher for the browser (client).
The traced processes will be the Firefox JavaScript engine and the Java process of the servlet engine (Jakarta Tomcat), embedded with NetBeans 5.5, with JRE 6.0. The Java tracing script is generic and can trace any Java 6.0 process, provided that we enableExtendedDTraceProbes by either specifying the JVM flag -XX:+ExtendedDTraceProbes at startup, or by using JDK 6.0 jinfo utility, which can enable/disable flags ( jinfo -flag +ExtendedDTraceProbes <Java-process-ID>).
Installations and Configuration
- Make sure you are running on Solaris Express build 63 or higher from OpenSolaris. I have tested on build 63.
- Download and install a DTrace instrumented Firefox.
- Make sure Java 6.0 is installed (default with recent Solaris Express builds).
- Download and install NetBeans 5.5.
- Download and unzip 4257_Ajaxbasics2.zip from Sang Shin's course lab.
- Configure NetBeans to use Firefox as the default browser (Tools/Options).
- In NetBeans, open the project Ajax-validation from <4257_Ajaxbasics2 unzipped directory>/Ajaxbasics2/samples
- Add “
-XX:+ExtendedDTraceProbes” flag to JAVA_OPTS in <netbeans-base-dir>/enterprise3/apache-tomcat-5.5.17/bin/catalina.sh. You might skip this and perform (4) in next sequence ('Running').
Running
- In NetBeans, right click on the Ajax-validation project you have created and choose 'Run Project'
- Check that JavaScript DTrace probes are enabled. Run:
#
dtrace -P 'trace_mozilla*' -l
|
You should see something like:
ID PROVIDER MODULE FUNCTION NAME 73007 trace_mozilla9547 libmozjs.so jsdtrace_execute_done js_execute-done 73008 trace_mozilla9547 libmozjs.so js_Execute js_execute-done 73009 trace_mozilla9547 libmozjs.so jsdtrace_execute_start js_execute-start 73010 trace_mozilla9547 libmozjs.so js_Execute js_execute-start 73011 trace_mozilla9547 libmozjs.so jsdtrace_function_entry js_function-entry 73012 trace_mozilla9547 libmozjs.so js_Interpret js_function-entry 73013 trace_mozilla9547 libmozjs.so jsdtrace_function_return js_function-return 73014 trace_mozilla9547 libmozjs.so js_Interpret js_function-return 73015 trace_mozilla9547 libmozjs.so jsdtrace_object_create js_object-create 73016 trace_mozilla9547 libmozjs.so js_NewObject js_object-create 73017 trace_mozilla9547 libmozjs.so jsdtrace_object_create_done js_object-create-done 73018 trace_mozilla9547 libmozjs.so js_NewObject js_object-create-done 73019 trace_mozilla9547 libmozjs.so jsdtrace_object_create_start js_object-create-start 73020 trace_mozilla9547 libmozjs.so js_NewObject js_object-create-start 73021 trace_mozilla9547 libmozjs.so jsdtrace_object_finalize js_object-finalize 73022 trace_mozilla9547 libmozjs.so js_FinalizeObject js_object-finalize |
- After the application page shows up in Firefox, locate the Java servlet engine (Tomcat) process (by pgrep -n java if you have not run any other JVM meanwhile, or by ' ptree NetBeans') and see the bottom Java process. Find the process ID.
- If you have not performed (8) in previous sequence, use this (as JVM-PID) and run
# jinfo -flag + ExtendedDTraceProbes <JVM-PID>
|
- Run:
# <dtrace script name> <JavaScript-engine-PID> <JVM-PID>.
|
This should be done as root user or as a DTrace privileged user.
Note:
There are naming changes expected for in the Mozilla Dtrace provider:
trace_mozilla* to javascript probe names will change from
js_X to X (i.e., js_function-entry to function-entry)
trace_mozilla*:::js_function-entryjavascript*:::function-entry
|
In this example, we are tracing the call flow of the JavaScript functions and the Java servlet methods, which responds to the Ajax calls. We are doing this by the following script ( javax_java_call_flow.d).
#!/usr/sbin/dtrace -Zs
#pragma D option quiet
#pragma D option switchrate=10
dtrace:::BEGIN
{
jsIndent = 0;
jsFile = "ajax-validation";
javaMethodBoundary= "doGet";
startTimestamp = timestamp;
}
*mozilla$1:::js_function-entry
/basename(copyinstr(arg0)) == jsFile/
{
jsIndent += 2;
printf("%*s -> %s:%s (JavaScript)(elapsed ms: %d)
", jsIndent, "",
jsFile, copyinstr(arg2), (timestamp - startTimestamp) / 1000);
}
*mozilla$1:::js_function-return
/basename(copyinstr(arg0)) == jsFile/
{
printf("%*s <- %s:%s (JavaScript)(elapsed ms: %d)
", jsIndent, "",
jsFile, copyinstr(arg2), (timestamp - startTimestamp) / 1000);
jsIndent -= 2;
}
hotspot$2:::method-entry
{
self->strPtr = (char *)copyin(arg1, args[2]+1);
self->strPtr[(int)args[2]] = ' ';
self->classStr = (string)self->strPtr;
self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
self->strPtr[(int)args[4]] = ' ';
self->methodStr = (string)self->strPtr;
}
hotspot$2:::method-entry
/javaMethodBoundary == self->methodStr/
{
self->interested = 1;
self->indent = 0;
}
hotspot$2:::method-entry
/self->interested/
{
self->indent += 2;
printf("%*s -> %s:%s (Java)(elapsed ms: %d)
", self->indent, "",
self->classStr, self->methodStr, (timestamp - startTimestamp) / 1000);
}
hotspot$2:::method-return
{
self->strPtr = (char *)copyin(arg1, args[2]+1);
self->strPtr[(int)args[2]] = ' ';
self->classStr = (string)self->strPtr;
self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
self->strPtr[(int)args[4]] = ' ';
self->methodStr = (string)self->strPtr;
}
hotspot$2:::method-return
/self->interested/
{
printf("%*s <- %s:%s (Java)(elapsed ms: %d)
", self->indent, "",
self->classStr, self->methodStr, (timestamp - startTimestamp) / 1000);
self->indent -= 2;
}
hotspot$2:::method-return
/javaMethodBoundary == self->methodStr/
{
self->interested = 0;
/* exit(0); */
}
|
Run the script like this (as a root or a DTrace privileged user):
# ajax_java_call_flow.d <JavaScript-engine-PID> <JVM-PID>
- JavaScript-engine-PID can be retrieved from the provider name in " dtrace -P 'trace_mozilla*' -l" output. For Example:
73007 trace_mozilla 9547 libmozjs.so jsdtrace_execute_done js_execute-done ( 9547 is the pid). - JVM-PID can be taken, after invoking the application, by running, for example, " ptree `pgrep -n netbeans`" and see the bottom Java process
- Type a character in the application form, wait 2 seconds and type <Ctrl-C> to stop the script. Check the script output.
The JavaScript probes (right after the BEGIN{} blocks:
*mozilla*:::js_function-entryis fired whenever a JavaScript function is called. A predicate is filtering out all calls besides those in the ajax-validation (arg0points to the URL in which the JavaScript function resides) URL. It prints the function name and the time passed from last function call/return, properly indented.*mozilla*:::js_function-returndoes the same for every 'ajax-validation' function return.
Then there are the Java probes
hotspot$target:::method-entryis fired whenever a Java method is called. There are a few action blocks here for the same probe, since we want to filter out calls which are not inside the boundaries of thedoGet()servlet method. Only when inside these boundaries, the probe prints class name, method name and time passed from last class:method call/return, in a proper indentationhotspot$target:::method-returndoes the same for every method return inside that boundaries.
The output will look like this (though much longer...):
-> ajax-validation:validateUserId (JavaScript)(elapsed ms: 4288375)
-> ajax-validation:escape (JavaScript)(elapsed ms: 4288497)
<- ajax-validation:escape (JavaScript)(elapsed ms: 4288514)
-> ajax-validation:initRequest (JavaScript)(elapsed ms: 4288529)
<- ajax-validation:initRequest (JavaScript)(elapsed ms: 4288588)
-> ajax-validation:open (JavaScript)(elapsed ms: 4288642)
<- ajax-validation:open (JavaScript)(elapsed ms: 4288955)
-> ajax-validation:send (JavaScript)(elapsed ms: 4288969)
<- ajax-validation:send (JavaScript)(elapsed ms: 4289758)
<- ajax-validation:validateUserId (JavaScript)(elapsed ms: 4289769)
-> com/sun/j2ee/blueprints/bpcatalog/ajax/ValidationServlet:doGet (Java)(elapsed ms: 4721275)
-> org/netbeans/modules/web/monitor/server/MonitorRequestWrapper:getParameter (Java)(elapsed ms: 4721289)
-> org/apache/catalina/connector/RequestFacade:getParameter (Java)(elapsed ms: 4721300)
-> java/lang/System:getSecurityManager (Java)(elapsed ms: 4721309)
<- java/lang/System:getSecurityManager (Java)(elapsed ms: 4721319)
-> org/apache/catalina/connector/Request:getParameter (Java)(elapsed ms: 4721330)
-> org/apache/catalina/connector/Request:parseParameters (Java)(elapsed ms: 4721341)
...
...
...
<- org/apache/tomcat/util/buf/CharChunk:min (Java)(elapsed ms: 4729143)
-> java/lang/String:getChars (Java)(elapsed ms: 4729156)
-> java/lang/System:arraycopy (Java)(elapsed ms: 4729166)
<- java/lang/System:arraycopy (Java)(elapsed ms: 4729176)
<- java/lang/String:getChars (Java)(elapsed ms: 4729185)
<- org/apache/tomcat/util/buf/CharChunk:append (Java)(elapsed ms: 4729196)
<- org/apache/catalina/connector/OutputBuffer:write (Java)(elapsed ms: 4729207)
<- org/apache/catalina/connector/CoyoteWriter:write (Java)(elapsed ms: 4729218)
<- org/apache/catalina/connector/CoyoteWriter:write (Java)(elapsed ms: 4729228)
<- com/sun/j2ee/blueprints/bpcatalog/ajax/ValidationServlet:doGet (Java)(elapsed ms: 4729242)
-> ajax-validation:getElementsByTagName (JavaScript)(elapsed ms: 4922548)
<- ajax-validation:getElementsByTagName (JavaScript)(elapsed ms: 4922644)
-> ajax-validation:setMessageUsingDOM (JavaScript)(elapsed ms: 4922782)
-> ajax-validation:getElementById (JavaScript)(elapsed ms: 4922812)
<- ajax-validation:getElementById (JavaScript)(elapsed ms: 4922866)
-> ajax-validation:createTextNode (JavaScript)(elapsed ms: 4923003)
<- ajax-validation:createTextNode (JavaScript)(elapsed ms: 4923040)
-> ajax-validation:replaceChild (JavaScript)(elapsed ms: 4923142)
<- ajax-validation:replaceChild (JavaScript)(elapsed ms: 4923437)
<- ajax-validation:setMessageUsingDOM (JavaScript)(elapsed ms: 4923449)
-> ajax-validation:getElementById (JavaScript)(elapsed ms: 4923471)
<- ajax-validation:getElementById (JavaScript)(elapsed ms: 4923523)
|
Each call (->) or return (<-) function/method shows the time passed from last call/return
Use this script with a special care for your applications: simultaneous Ajax requests and several servlet threads might make some mess in the output. This example shows one Java thread. In a more complex environment, especially if we are only interested in understanding the flow, it might make sense to serialize the application threads by using only one CPU (if you are running on a multi core/CPU machine). Look for pbind andpsrset Solaris main pages, for more information on restricting the application to specific CPU[s].
|
You can also show inclusive function time by changing the previous script to do that (ajax_java_functions.d).
#!/usr/sbin/dtrace -Zs
#pragma D option quiet
#pragma D option switchrate=10
dtrace:::BEGIN
{
jsFile = "ajax-validation";
JavaMethodBoundary = "doGet";
}
*mozilla$1:::js_function-entry
/basename(copyinstr(arg0)) == jsFile/
{
depth++;
jsFEntry[copyinstr(arg2), depth] = vtimestamp;
}
*mozilla$1:::js_function-return
/basename(copyinstr(arg0)) == jsFile/
{
@jsFTimes[copyinstr(arg2)] = sum(vtimestamp - jsFEntry[copyinstr(arg2), depth]);
depth--;
}
hotspot$2:::method-entry
{
self->strPtr = (char *)copyin(arg1, args[2]+1);
self->strPtr[(int)args[2]] = ' ';
self->classStr = (string)self->strPtr;
self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
self->strPtr[(int)args[4]] = ' ';
self->methodStr = (string)self->strPtr;
}
hotspot$2:::method-entry
/JavaMethodBoundary == self->methodStr/
{
self->interested = 1;
}
hotspot$2:::method-entry
/self->interested/
{
self->depth++;
javaFEntry[self->classStr, self->methodStr, self->depth] = vtimestamp;
}
hotspot$2:::method-return
{
self->strPtr = (char *)copyin(arg1, args[2]+1);
self->strPtr[(int)args[2]] = ' ';
self->classStr = (string)self->strPtr;
self->strPtr = (char *)copyin(arg3, (int)args[4]+1);
self->strPtr[(int)args[4]] = ' ';
self->methodStr = (string)self->strPtr;
}
hotspot$2:::method-return
/self->interested/
{
@javaFTimes[self->classStr, self->methodStr] = sum(vtimestamp - javaFEntry[self->classStr, self->methodStr,
self->depth]);
self->depth--;
}
hotspot$2:::method-return
/JavaMethodBoundary == self->methodStr/
{
self->interested = 0;
}
END
{
normalize(@jsFTimes, 1000);
normalize(@javaFTimes, 1000);
printf("JavaScript Functions
");
printf("--------------------
");
printf("%-10s %-25s
", "inc. time", "Function");
printa("%@-10u %-25s
", @jsFTimes);
printf("
");
printf("Java Methods
");
printf("------------
");
printf("%-10s %-50s %s
", "inc. time", "Class", "Method");
printa("%@-10u %-50s %s
", @javaFTimes);
}
|
Run the script like this (as a root or a DTrace privileged user):
# ajax_java_functions.d <JavaScript-engine-PID> <JVM-PID>
- JavaScript-engine-PID can be retrieved from the provider name in dtrace -P 'trace_mozilla*' -l output. For Example:
73007 trace_mozilla 9547 libmozjs.so jsdtrace_execute_done js_execute-done ( 9547 is the pid). - JVM-PID can be taken, after running the application by running, for example, “ ptree `pgrep -n netbeans`” and see the bottom Java process
- <Ctrl-C> once you would like to stop your tracing, and results will show up in standard output
That produced the output below on my machine. First column shows inclusive execution time (in milliseconds, some Java methods might return zero after moving from nanoseconds to milliseconds). Inclusive time means the time spent in the function/method, including all function/method calls inside the function body. Net time spent in a function/method, excluding time spent in methods/calls contained in its body, is called exclusive time.
See below the last processParameters() method, with an inclusive time which is bigger than doGet() method, in which it is contained. This is becauseprocessParameters() is recursive. Since we consider inclusive time, recursive function have overlapped time, which is counted more than once.
JavaScript Functions -------------------- inc. time Function 5 escape 29 createTextNode 59 initRequest 84 getElementsByTagName 89 getElementById 295 replaceChild 318 open 465 send 569 setMessageUsingDOM 1048 validateUserId Java Methods ------------ inc. time Class Method 0 org/apache/tomcat/util/buf/CharChunk min 0 org/apache/tomcat/util/http/ContentType getCharsetFromContentType 0 org/apache/tomcat/util/buf/MessageBytes toString ... ... ... 94 org/apache/catalina/connector/ResponseFacade setHeader 100 javax/servlet/http/HttpServletResponseWrapper setHeader 191 java/lang/StringCoding$StringDecoder decode 372 java/lang/StringCoding decode 384 java/lang/String <init> 388 org/apache/tomcat/util/buf/ByteChunk toStringInternal 455 org/apache/tomcat/util/buf/StringCache toString 459 org/apache/tomcat/util/buf/ByteChunk toString 492 org/apache/tomcat/util/http/Parameters urlDecode 585 org/apache/tomcat/util/http/Parameters handleQueryParameters 664 org/apache/catalina/connector/Request parseParameters 680 org/apache/catalina/connector/Request getParameter 688 org/apache/catalina/connector/RequestFacade getParameter 691 org/netbeans/modules/web/monitor/server/MonitorRequestWrapper getParameter 927 com/sun/j2ee/blueprints/bpcatalog/ajax/ValidationServlet doGet 1082 org/apache/tomcat/util/http/Parameters processParameters |
In many cases, though, we are more interested in exclusive function times. This let us quickly realize the hotspots in our applications. I have used the previous script (ajax_java_call_flow.d) output, which I redirected to a file, and processed it with a Perl script (ajax_java_time_from_callflow.pl):
Run:
#
ajax_java_call_flow.d <JavaScript-engine-PID> <JVM-PID> > <output-file>
#
perl
ajax_java_time_from_callflow.txt
<output-file>
|
This will create a list of all function/methods (mixed JavaScript and Java), their exclusive and inclusive time. The list is sorted in a descending order of the functions exclusive time.
Method/Function Exc. time Inc. time ajax-validation:send 789 789 ajax-validation:open 313 313 ajax-validation:replaceChild 295 295 ajax-validation:setMessageUsingDOM 281 667 java/lang/StringCoding$StringDecoder:decode 252 1944 sun/nio/cs/UTF_8$Decoder:decodeArrayLoop 244 429 ajax-validation:validateUserId 216 1394 org/apache/tomcat/util/buf/MessageBytes:equalsIgnoreCase 213 314 |
We can go further and trace system calls time by adding these probes (tracing here is not limited to the doGet() function boundaries)
syscall:::entry
/pid == $2/
{
scEntry[probefunc] = vtimestamp;
}
syscall:::return
/pid = $2/
{
@scTimes[probefunc] = sum(vtimestamp - scEntry[probefunc]);
}
and adding these lines to the END clause to do the printing:
END
{
...
normalize(@scTimes, 1000);
printf("System Calls
");
printf("------------
");
printf("%-10s %-50s
", "inc. time", "Syscall");
printa("%@-10u %-50s
", @scTimes);
}
|
We can trace every aspect of the system (network, I/O, processes, etc.) using DTrace. For basic DTrace utilities that cover most systems aspects, see the DTrace toolkit.
|
We have seen how you can trace a joint JavaScript and Java call flow using DTrace. We have also seen how to trace JavaScript function times and Java method times. Each tracing task might have probably done with a specialized profiling tool. DTrace offers one tool that can replace them all. Finding out where does your application spend most of the time, no matter if these are Java methods, JavaScript function, or system activity done on behalf of a user function. No need to deal with a variety of tools, each capable of doing a partial task. DTrace technology lets you trace everything you want in the system.