jcon.no: Oracle blog

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.