The sample D scripts in this section show how to use Enterprise Server DTrace probes to monitor Enterprise Server.
This example traces network connection activity, such as the opening and closing of network connections, and the addition and removal of tasks from the task queue. Each time an operation on a network connection is performed, the probe for that operation and the probe's parameters are displayed on standard output.
Line breaks are added to the printf() statements in this example to enhance readability. In an actual D script, the added line breaks would cause the script to fail to compile.
#!/usr/sbin/dtrace -Zs dtrace:::BEGIN { printf("%-Y Starting DTrace...\n", walltimestamp); i=0; } glassfish*:kernel:connection-queue:connectionAcceptedEvent { listenerName=copyinstr(arg0); connection=arg1; address=copyinstr(arg2); printf("connectionAcceptedEvent(listenerName=%s,connection=%d,address=%s)", listenerName,connection,address); } glassfish*:kernel:connection-queue:connectionClosedEvent { listenerName=copyinstr(arg0); connection=arg1; printf("connectionClosedEvent(listenerName=%s,connection=%d)",listenerName, connection); } glassfish*:kernel:connection-queue:connectionConnectedEvent { listenerName=copyinstr(arg0); connection=arg1; address=copyinstr(arg2); printf("connectionConnectedEvent(listenerName=%s,connection=%d,address=%s)", listenerName,connection,address); } glassfish*:kernel:connection-queue:onTaskQueuedEvent { listenerName=copyinstr(arg0); task=copyinstr(arg1); printf("onTaskQueuedEvent(listenerName=%s,task=%s)",listenerName,task); } glassfish*:kernel:connection-queue:onTaskDequeuedEvent { listenerName=copyinstr(arg0); task=copyinstr(arg1); printf("onTaskDequeuedEvent(listenerName=%s,task=%s)",listenerName,task); } glassfish*:kernel:connection-queue:onTaskQueueOverflowEvent { listenerName=copyinstr(arg0); printf("onTaskQueueOverflowEvent(listenerName=%s)",listenerName); } glassfish*:kernel:connection-queue:setMaxTaskQueueSizeEvent { listenerName=copyinstr(arg0); size=arg1; printf("setMaxTaskQueueSizeEvent(listenerName=%s,size%d)",listenerName,size); } dtrace:::END { printf("%-Y Finished DTrace of glassfish*...\n", walltimestamp); }
This script can be run with a command similar to the following:
# /usr/sbin/dtrace -s http-conn.d |
Information similar to the following is displayed.
dtrace: script 'http-conn.d' matched 9 probes CPU ID FUNCTION:NAME 0 1 :BEGIN 2009 Dec 2 18:19:27 Starting DTrace... 0 40548 connection-queue:connectionAcceptedEvent connectionAcceptedEvent( listenerName=admin-listener,connection=5676699,address=/129.146.11.144:50600) 0 40549 connection-queue:onTaskQueuedEvent onTaskQueuedEvent( listenerName=admin-listener,task=13872330) 0 40550 connection-queue:onTaskDequeuedEvent onTaskDequeuedEvent( listenerName=admin-listener,task=13872330) 0 40549 connection-queue:onTaskQueuedEvent onTaskQueuedEvent( listenerName=admin-listener,task=17098630) 0 40550 connection-queue:onTaskDequeuedEvent onTaskDequeuedEvent( listenerName=admin-listener,task=17098630) 0 40549 connection-queue:onTaskQueuedEvent onTaskQueuedEvent( listenerName=admin-listener,task=16525461) 0 40550 connection-queue:onTaskDequeuedEvent onTaskDequeuedEvent( listenerName=admin-listener,task=16525461) 0 40548 connection-queue:connectionAcceptedEvent connectionAcceptedEvent( listenerName=admin-listener,connection=13390280,address=/129.146.11.144:50601) |
The script runs until a user types Ctrl-C to stop the script.
This example traces HTTP requests to the web container and calculates the time that is required to handle each request. Each time a request is handled, details of the request and the time in microseconds to handle the request are displayed on standard output. When the script is stopped, it displays a summary of the requests that were handled while the script was running.
#!/usr/sbin/dtrace -Zs dtrace:::BEGIN { printf ("%-20s \n", "Monitoring Requests"); total = 0; } glassfish$1:web:http-service:requestStartEvent { self->ts = timestamp; trace(probename); @counts[probename]=count(); } glassfish$1:web:http-service:requestEndEvent /self->ts/ { trace(probename); printf ("%s %s %d\n", copyinstr(arg0), copyinstr(arg1), arg2); @counts[probename]=count(); @time[execname] = quantize(timestamp - self->ts); printf ("time in microseconds: %d\n", (timestamp - self->ts)); self->ts = 0; total++; } dtrace:::END { printf ("Total requests = %d\n", total); }
This script requires the process ID of the Enterprise Server process. The process ID can be obtained with the following command:
# jps | grep ASMain 1086 ASMain |
In this example, the process ID of the Enterprise Server process is 1086.
This script can be run with a command similar to the following:
# /usr/sbin/dtrace -s trace-web-requests.d 1086 |
Information similar to the following is displayed. For better readability, the spacing between columns is reduced.
dtrace: script 'trace-web-requests.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Monitoring Requests 0 41085 http-service:requestStartEvent requestStartEvent 0 41084 http-service:requestEndEvent requestEndEvent hello server 3418876592 time in microseconds: 70935041 0 41085 http-service:requestStartEvent requestStartEvent 0 41084 http-service:requestEndEvent requestEndEvent hello server 3419925040 time in microseconds: 2174591 0 41085 http-service:requestStartEvent requestStartEvent 0 41084 http-service:requestEndEvent requestEndEvent hello server 3418876592 time in microseconds: 13554111 0 41085 http-service:requestStartEvent requestStartEvent 0 41084 http-service:requestEndEvent requestEndEvent hello server 3419925040 time in microseconds: 2499509 |
The script runs until a user types Ctrl-C to stop the script. When the script stops, information similar to the following is displayed.
^C 0 2 :END Total requests = 4 requestEndEvent 4 requestStartEvent 4 java value ------------- Distribution ------------- count 1048576 | 0 2097152 |@@@@@@@@@@@@@@@@@@@@ 2 4194304 | 0 8388608 |@@@@@@@@@@ 1 16777216 | 0 33554432 | 0 67108864 |@@@@@@@@@@ 1 134217728 | 0 |