Thursday March 05, 2009

Using DTrace in Sun Java System Web Server - part 2

Using DTrace in Sun Java System Web Server - part 2

In my previous blog I was just tracing the flow of request processing, in this blog I have tried to see how much time it takes when <If>/ <Client> tags etc. are evaluated.

Add in obj.conf the following lines to disable accelerator cache

AuthTrans fn="log" level="fine" message="Accelerator cache disabled"

Add one "If" condition in obj.conf

<If $uri =~ "/test.html">

Service method="(GET|HEAD|POST)" type="*~magnus-internal/*" fn="send-file"

</If>

Check webservd's pid

$ps -eaf | grep webservd | grep highest pid

Run this DTrace script, send a request to GET /test.html HTTP/1.0 via telnet from another window.

Here is the output :

$./ws.d highest-pid thread 24: Added connection 0x29b3228 to connectionQ thread 29: Removed connection 0x29b3228 from connectionQ. Time spent in Q 81250 nanoseconds thread 29: Processing for absolute path /test.html client ip xxx.xxx.xxx.xxx thread 29: processing objects for uri /test.html thread 29: object-check called thread 29: object-check finished. Time spent 8584 nanoseconds thread 29: Calling saf match-browser thread 29: saf match-browser returned -2. Time spent is 66916 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2917 nanoseconds thread 29: Calling saf ntrans-j2ee thread 29: saf ntrans-j2ee returned -2. Time spent is 26084 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2417 nanoseconds thread 29: Calling saf pfx2dir thread 29: saf pfx2dir returned -2. Time spent is 21500 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 3500 nanoseconds thread 29: Calling saf uri-clean thread 29: saf uri-clean returned 0. Time spent is 21750 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2500 nanoseconds thread 29: Calling saf find-pathinfo thread 29: saf find-pathinfo returned -2. Time spent is 10750 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2250 nanoseconds thread 29: Calling saf find-index-j2ee thread 29: saf find-index-j2ee returned -2. Time spent is 8917 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2250 nanoseconds thread 29: Calling saf find-index thread 29: saf find-index returned -2. Time spent is 9000 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2750 nanoseconds thread 29: Calling saf type-j2ee thread 29: saf type-j2ee returned 0. Time spent is 11584 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2334 nanoseconds thread 29: Calling saf type-by-extension thread 29: saf type-by-extension returned 0. Time spent is 38750 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 2833 nanoseconds thread 29: Calling saf force-type thread 29: saf force-type returned 0. Time spent is 10833 nanoseconds thread 29: cond-eval called thread 29: expr-eval called thread 29: expr-compiled-re-eval subject /test.html match 1 pattern /test.html, return value 1 thread 29: expr-eval finished. Time spent 65584 nanoseconds thread 29: cond-eval finished. Time spent 111500 nanoseconds thread 29: Calling saf send-file thread 29: saf send-file returned 0. Time spent is 102583 nanoseconds thread 29: object-check called thread 29: object-check finished. Time spent 3166 nanoseconds thread 29: Calling saf flex-log thread 29: saf flex-log returned 0. Time spent is 47833 nanoseconds

This shows how much time was spent in each SAF, when connection was put in connection queue and when it was removed and which regular expression in obj.conf was evaluated, how much time was spent, what was the result.

Attached are the cvs diffs and ws.d script

 Summary

These DTrace probes will help us to dynamically find out

1. Which request processing stages were called for a request,  how much time each request processing stage took for a particular request.
   
2. When was a connection put into connection queue (Requests in Web server are accepted by acceptor threads and put in connection queue and picked up by Worker threads) so if the requests sit for a long time in connection queue, then worker threads settings in server.xml configuration file should be increased accordingly.
3. Which regular expression in obj.conf was evaluated, how much time was spent, what was the result.