Thursday Mar 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.


Tuesday Nov 18, 2008

Tracing the flow of request processing using DTrace in Sun Java System Web Server

Tracing the flow of request processing using DTrace in Sun Java System Web Server

I am trying to add basic DTrace probes in Sun Java System Web Server 7.0. I will start by adding probes that let us know which SAF got executed at run time. Let me know if you have any ideas.

I start the server instance and run this script ws.d and send a few requests :

$./ws.d highest-pid
thread 29: Calling saf match-browser
thread 29: saf match-browser returned -2
thread 29: Calling saf ntrans-j2ee
thread 29: saf ntrans-j2ee returned -2
thread 29: Calling saf pfx2dir
thread 29: saf pfx2dir returned -2
thread 29: Calling saf uri-clean
thread 29: saf uri-clean returned 0
thread 29: Calling saf find-pathinfo
thread 29: saf find-pathinfo returned -2
thread 29: Calling saf find-index-j2ee
thread 29: saf find-index-j2ee returned -2
thread 29: Calling saf find-index
thread 29: saf find-index returned -2
thread 29: Calling saf type-j2ee
thread 29: saf type-j2ee returned 0
thread 29: Calling saf type-by-extension
thread 29: saf type-by-extension returned 0
thread 29: Calling saf force-type
thread 29: saf force-type returned 0
thread 29: Calling saf send-file
thread 29: Calling saf insert-filter
thread 29: saf insert-filter returned -2
thread 29: saf send-file returned 0
thread 29: Calling saf flex-log
thread 29: saf flex-log returned 0
thread 32: Calling saf match-browser
thread 32: saf match-browser returned -2
thread 32: Calling saf ntrans-j2ee
thread 32: saf ntrans-j2ee returned -2
thread 32: Calling saf pfx2dir
thread 32: saf pfx2dir returned -2
thread 32: Calling saf uri-clean
thread 32: saf uri-clean returned 0
thread 32: Calling saf find-pathinfo
thread 32: saf find-pathinfo returned -2
thread 32: Calling saf find-index-j2ee
thread 32: saf find-index-j2ee returned -2
thread 32: Calling saf find-index
thread 32: saf find-index returned -2
thread 32: Calling saf type-j2ee
thread 32: saf type-j2ee returned 0
thread 32: Calling saf type-by-extension
thread 32: saf type-by-extension returned 0
thread 32: Calling saf force-type
thread 32: saf force-type returned 0
thread 32: Calling saf send-file
thread 32: Calling saf insert-filter
thread 32: saf insert-filter returned -2
thread 32: saf send-file returned 0
thread 32: Calling saf flex-log
thread 32: saf flex-log returned 0


If you want to call this only for a particular SAF lets say send-file modify ws.d to ws-saf.d

$./ws-saf.d 16186
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
thread 29: Calling saf send-file
thread 29: saf send-file returned 0
...


I added these 2 files and these cvs diffs in iplanet/ias/server/src/cpp/iws/netsite/lib/frame/ directory and compiled Web Server gmake all publish; cd ../httpd/src; gmake clobber all publish. Note that I have kept DTrace probes signature as some important parameters, followed by Pblock, Session, Request structure pointers just in case at any point of time we need to find out values of some of these.

sjsws.d
sjsws.h
diff.txt

Friday Oct 24, 2008

DTrace script to collect information about cipher suites used

DTrace script to collect information about cipher suites used

Here is a script I have to trace SSL calls. Running this script on a Web Server instance (32 bit ) pid lets say in our case is 9149. Sending some SSL requests on to this server :

There are two ways to run this log=normal and log=verbose. Pressing control C returns the statistical data.

$./ssltop.d 9149 log=normal
t@26: 2008 Oct 30 16:50:56: 129.158.224.109 Connection created
t@26: 2008 Oct 30 16:50:56: ListenSocket::accept called
t@30: 2008 Oct 30 16:50:56: 129.158.224.109 Negotiated cipher RC4
t@33: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@26: 2008 Oct 30 16:51:06: 129.158.224.109 Connection created
t@26: 2008 Oct 30 16:51:06: ListenSocket::accept called
t@33: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@33: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@33: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@33: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@33: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
t@30: 2008 Oct 30 16:51:06: 129.158.224.109 Negotiated cipher AES-256
\^C
SSL Functions Called
--------------------
count      Function
SSL Ciphers used
--------------------
count      cipher suite
1          RC4
13         AES-256

 Running in verbose mode gives more information :

$./ssltop.d 9149 log=verbose
t@32: 2008 Oct 30 16:50:13: Entered ssl3_GatherAppDataRecord ...
t@32: 2008 Oct 30 16:50:13: Entered ssl3_GatherCompleteHandshake ...
t@32: 2008 Oct 30 16:50:13: Entered ssl3_GatherData ...
t@35: 2008 Oct 30 16:50:13: Entered ssl3_GatherAppDataRecord ...
t@35: 2008 Oct 30 16:50:13: Entered ssl3_GatherCompleteHandshake ...
t@35: 2008 Oct 30 16:50:13: Entered ssl3_GatherData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_HandleRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_HandleRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@35: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@35: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_HandleRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_HandleRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_HandleRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@32: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_HandleRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@35: 2008 Oct 30 16:50:14: 129.158.224.109 Negotiated cipher AES-256
t@35: 2008 Oct 30 16:50:14: Entered ssl3_SendApplicationData ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_SendRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ClientAuthTokenPresent ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_CompressMACEncryptRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_ComputeRecordMAC ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_BumpSequenceNumber ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_GatherAppDataRecord ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_GatherCompleteHandshake ...
t@35: 2008 Oct 30 16:50:14: Entered ssl3_GatherData ...
\^C
SSL Functions Called
--------------------
count      Function
13         ssl3_HandleRecord
15         ssl3_CompressMACEncryptRecord
15         ssl3_GatherAppDataRecord
15         ssl3_GatherCompleteHandshake
15         ssl3_GatherData
15         ssl3_SendApplicationData
15         ssl3_SendRecord
28         ssl3_BumpSequenceNumber
28         ssl3_ClientAuthTokenPresent
28         ssl3_ComputeRecordMAC
SSL Ciphers used
--------------------
count      cipher suite
13         AES-256
About

Meena Vyas

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