X

Blogs about Deep Learning, Machine Learning, AI, NLP, Security, Oracle Traffic Director,Oracle iPlanet WebServer

  • March 5, 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.


Be the first to comment

Comments ( 0 )
Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.