One important task when working with Oracle trace is to distinguish between idle and significant “SQL*Net message from client” waits. Default, MethodR defines waits above 1 second as “think time”. These waits are usually identified as idle waits. For instance – in an application using a connection pool, the sessions will be waiting for a client thread to grab a connection. These waits are truly not tied to the application response times, but is idle waits. In this article I’ll show how these waits easily can be “removed” or neutralized by using the MethodR utilities.
This profile is from a session tied to a perl process polling a message queue for more work every second. The Oracle session is only used when work is found. 99,7 % of the time the session is waiting for something to do. This is the “SQL*Net message from client” waits, both think time and the other waits. Now we need to remove the idle waits from this trace file.
The first line of this profile shows the “SQL*Net message from client [think time]”. This is the “SQL*Net message from client” waits above 1 second. This profile shows that the minimum wait time for this wait event is 1.102646 seconds, and the maximum wait time is 12.201795 seconds.
First we use the mrskew utility to find all the line numbers tied to “SQL*Net message from client” above 1 second:
# mrskew --group=$line --glabel=LINE --name=SQL\*Net message from client --where=$ela>1 --top=0 orcl_ora_1945836.trc > tmp_lines_org.txt
The report (tmp_lines_org.txt) looks like this:
LINE DURATION % CALLS MEAN MIN MAX ---------- ---------- ------ ----- --------- --------- --------- 7875 12.201795 5.7% 1 12.201795 12.201795 12.201795 1274 10.839537 5.1% 1 10.839537 10.839537 10.839537 2846 9.863728 4.6% 1 9.863728 9.863728 9.863728 ... 6117 1.195462 0.6% 1 1.195462 1.195462 1.195462 2858 1.102646 0.5% 1 1.102646 1.102646 1.102646 ---------- ---------- ------ ----- --------- --------- --------- TOTAL (42) 212.520905 100.0% 42 5.060022 1.102646 12.201795
I manually remove the header and footer lines, leaving only the rows with the line number in the first posistion. Then I use “awk” to extract the line numbers and to add a comma, and “sed” to remove the linefeeds:
# awk '{print $1}”,”' tmp_lines_org.txt > tmp_line_numbers.txt # sed ':a;N;$!ba;s/\n//g' tmp_line_numbers > rm_lines.txt
Now we are ready to neutralize the “SQL*Net message from client” waits with the mrcallrm tool:
mrcallrm –-lines=`cat rm_lines.txt` orcl_ora_1945836.trc > orcl_ora_1945836_new.trc
Note! Actually the lines are not removed, but the time measures for the given lines are neutralized. The following shows the line 526 before and after the line is “removed” or neutralized.
Before:
525: WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=197679 tim=61801870903761 526: WAIT #7: nam='SQL*Net message from client' ela= 5458287 driver id=1413697536 #bytes=1 p3=0 obj#=197679 tim=61801876362074
After:
525: WAIT #7: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=197679 tim=61801870903761 526: WAIT #7: nam='SQL*Net message from client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=197679 tim=61801870903787
Now if we generate a MethodR profiler report on the new trace file (orcl_ora_1945836_new.trc), we get the following:
The “SQL*Net message from client” is still the major wait event. In the further analysis I definitely need to consider if more of this waits should be considered idle. Knowing the order of the SQLs coming from the application, I can look at the raw trace file and identify if the idle waits go lower than 1 second. If this is the case I can use the same procedure with – for instance – “ela>0.5”.
Note! If your are using Windows and DOS, the approach and commands is a little different. First the mrskew command:
DOS> mrskew --group="$line" --glabel=LINE --name="SQL\*Net message from client" --where="$ela>0.5" --top=0 orcl_ora_1945836.trc
To use the “awk”, “sed” and mrcallrm with the “cat” commands I recommend the MobaXterm utility. This utility gives you a “unix” prompt in windows.
Post a Comment