正文
End-to-End Tracing of Ajax/Java Applications Using DTrace
提示：扫一扫查出行【扫一扫了解最新限行尾号】
复制提示
End-to-End Tracing of Ajax/Java Applications Using DTrace
| By Amit Hurvitz, July 2007 |
 |
Ajax, DTrace and Where They Meet
|
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.
An Ajax Application Tracing Example
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>).
To run the examples:
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:
# |
You should see something like:
ID PROVIDER MODULE FUNCTION NAME |
- 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:
module name will change from
probe names will change from
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
Tracing Ajax and Java Call Flow
|
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 |
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) |
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].
Profiling Ajax and Java Functions/Methods times
|
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 |
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 |
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:
# |
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 |
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 |
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.
Conclusion
|
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.
For More Information
