Network Monitoring Experimentations 4

Previous articles in this series showed a number of interesting troubleshooting techniques that take advantage of the Wireshark packet capture utility. A recent OTN thread made me wonder if there isn’t a lot more than Wireshark offers, which might be helpful to Oracle DBAs. To demonstrate, first we need to create a simple test table with 1,000 rows:

It might be interesting to determine how SQL*Plus was able to indicate the number of consistent gets, sorts, and various other information. First, let’s take a look at the raw 10046 trace file that was generated:

After the SQL statement finished executing the execution plan for the SQL statement was written to the trace file, a COMMIT was executed that did not affect any data, and then this SQL statement appeared:

The 10046 trace file successfully hid how SQL*Plus was able to determine the number of consistent gets, sorts, and various other information for the SQL statement. It must be magic? Or maybe something else is happening… such as the creation of a secondary session to retrieve the statistics. Maybe Wireshark is able to help answer the question (note that some information in the Wireshark output is obscured – possibly you would not want someone seeing that information, or for that matter any of this “clear text” information, which would be clearly visible to all computers on a wireless network, as well as on networks that utilize hubs rather than switches, if the Oracle Advanced Security Option is not purchased and enabled).

There were two unrelated packets at the start of the Wireshark capture, so I right-clicked the first packet of interest and set it to be the Time Reference packet. The data section of the first packet of interest shows the ALTER SESSION command that enabled the 10046 trace:

—

A couple of packets later we see the first SQL statement that was not explicitly executed in our test script:

Packet 24 shows the retrieval of the first row from the database, on the lines between bytes 0150 (336 in decimal) and 0170 (368 in decimal). Packet 25 contains the request for the next set of 100 rows, and packet 26 begins the transmission of those 100 rows.

—

Packet 75 shows another SQL statement that was not explicitly included in the test script – this SQL statement also was not included in the 10046 trace file. The SQL statement retrieves the ending statistics for the session, allowing SQL*Plus to display the output of the delta values for those statistics.

—

One of the problems when reviewing the packet trace output, of course, is that it is difficult to see the full picture of what is happening. Wireshark allows right-clicking one of the packets in the conversation and then offers the option of Follow TCP Stream. For example, this is the Follow TCP Stream output at the start of the test script execution, with the red colored text showing the client-side transmitted data and the blue colored text showing the server transmitted data.

—

Scrolling down a little further we see the SQL statement used to determine the STATISTIC# values, followed by the SQL statement that was executed in the secondary session which determined the current statistic values for the session of interest.

—

At the end of the transfer we see the last row sent by the database server containing the row with a column value of A1000Z, immediately followed by the SQL statement that was executed in the secondary session which determined the ending statistic values for the session of interest:

—

There were a lot of . (period) characters in the Raw output, designating unprintable characters. Might some of these unprintable characters be the missing number column, the missing date column, or various control characters? Switching to the Hex Dump view might be helpful. In the below picture we see the SQL statement from our script, followed by a single row returned from the database, followed by another fetch call from the client, followed by the next 100 rows from the database.

How do I know that the client is retrieving the next 100 rows? Take a close look at the number displayed to the right of 00000DAF, in position 00000DB0. The hexidecimal number 64 (100 in decimal) appears in that position. How do I know that this is the number of requested rows? A simple test script will confirm that the number of requested rows appears in that byte position:

SET AUTOTRACE TRACEONLY STATISTICS
SET ARRAYSIZE 10
SELECT
*
FROM
T10
ORDER BY
C1;
SET ARRAYSIZE 50
SELECT
*
FROM
T10
ORDER BY
C1;
SET ARRAYSIZE 100
SELECT
*
FROM
T10
ORDER BY
C1;
SET ARRAYSIZE 500
SELECT
*
FROM
T10
ORDER BY
C1;

The byte containing the array size indicator seems to be incorrect when the fetch array size is set to 500 – F4 is equivalent to the decimal number 244. True, but F401, or with the high byte first, 01F4 is equivalent to the decimal number 500.

—

As a late edition to this blog article, I submitted the same SQL statement using a client that is able to retrieve the full fetch array size of 100 in the first fetch call. Below is the packet capture for that execution – compare the packet capture with the last of the above pictures to see if you are able to determine where SQL*Plus specified that the array fetch size for the first fetch should be only 1, rather than the user specified 100.

—

A search through YouTube locates a number of helpful Wireshark videos, including this one that shows how to use the Follow Stream feature.

So, the question remains, how do we decode the rest of the conversation between the client and server? For instance, what happened to the number and date column values in the packet capture? Does this OTN tread provide a clue?

I appreciate your help with decoding the data section of the packet. I admit to not spending very much time as of yet in trying to decode that section of the packet – that process was planned for a later blog article.

This output almost matches the hex numbers that were originally supplied to your anonymous PL/SQL block, and that were originally found in the packet capture:
’78 6e 05 18 08 1f 18′

23 decimal = 17 hex, off by 1
30 decimal = 1E hex, off by 1
7 decimal = 7 hex, off by 1
24 decimal = 18 hex – just when you think that there is a pattern, a curve ball is thrown, the same value
5 decimal = 5 hex, the same value
… and then we are completely lost.

After seeing your reply, I started to think that there must be another way to do this without using an anonymous PL/SQL block – just standard SQL, something like UTL_RAW.CAST_TO_VARCHAR2, but instead casting it to a date. After a couple of minutes of playing around, I searched and ended up on this page: http://mwidlake.wordpress.com/2010/01/03/decoding-high_value-and-low_value/

In short, you saved me a lot of time hopelessly digging around, trying to determine why I was receiving values that did not match the output of DUMP. I am not sure that I would have found the same solution as you did.

The problem you’ve pointed out above is one of those annoying inconsistencies with Oracle. Data type 13 (Typ=13) is an in-memory representation of dates used by PL/SQL and the date functions like TO_DATE. Dan Morgan has more details on Morgan’s library athttp://www.morganslibrary.org/reference/datatypes.html

A DATE data type from a table will be type 12 (and 7 bytes, rather than 8 ) and match my example above. Just try the DUMP function against the date column from your actual table and it should all make sense.

I have a faint memory of a conversation either in a Usenet thread or an OTN thread about the 7 byte and 8 byte date datatype difference that you mentioned. I thought that I participated in that discussion, but I can’t find it in a Google search. Thanks for mentioning this date data type difference – I probably would have spent a little more time trying to decode the raw packet if I had not hit a brick wall with the date datatype.

A demonstration of what you described (so that hopefully I will remember the next time I encounter this difference):

That exactly matches what was found in the network packet, using your example.

The web page that you linked contains the following:
“Oracle’s stores DATE in total of 7 bytes. Each byte in it stores values for an element of the DATE as follows:
Byte Description
1 Century value but before storing it add 100 to it
2 Year and 100 is added to it before storing
3 Month
4 Day of the month
5 Hours but add 1 before storing it
6 Minutes but add 1 before storing it
7 Seconds but add 1 before storing it”

Which oddly brings me back to my previous investigation that lead to the “brick wall”, reading the bytes from right to left:
’78 6e 05 18 08 1f 18′

23 decimal = 17 hex, off by 1
30 decimal = 1E hex, off by 1
7 decimal = 7 hex, off by 1
24 decimal = 18 hex – just when you think that there is a pattern, a curve ball is thrown, the same value
5 decimal = 5 hex, the same value
… and then we are completely lost.

While searching Google I did find an interesting test case that I posted a year ago, now I have a topic for tomorrow’s blog article.

Thank you for stopping by my blog and leaving the comment about the blog article. I hope that your found “Network Monitoring Experimentations 5″ to be decent also – that blog article took a bit longer than this one to put together.

On a side note, it is great to see the uptick of good information about Oracle’s behavior flowing across the Internet in the last couple of years. A portion of that opinion might have to do with the hit or miss nature of some Google searches, so if I find something interesting, I try to link to it so that it is easier to find again later. The new OakTable.net website has an improved Google search feature, so that is now an option in place of a standard Google search (but I will probably continue to link to helpful articles).

Hints for Posting Code Sections in Comments

********************
When the spacing of text in a comment section is important for readability (execution plans, PL/SQL blocks, SQL, SQL*Plus output, etc.) please use a <pre> tag before the code section and a </pre> tag after the code section:

<pre>

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;
TODAY
---------
01-MAR-12

</pre>
********************
When posting test case samples, it is much easier for people to reproduce the test case when the SQL*Plus line prefixes are not included - if possible, please remove those line prefixes. This:

SELECT
SYSDATE TODAY
FROM
DUAL;

Is easier to execute in a test case script than this:

SQL> SELECT
2 SYSDATE TODAY
3 FROM
4 DUAL;

********************
Greater than and Less than signs in code sections are often interpretted as HTML formatting commands. Please replace these characters in the code sections with the HTML equivalents for these characters: