April 25, 2010
(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)
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:
CREATE TABLE T10( C1 NUMBER, C2 VARCHAR2(12), C4 CHAR(12), C3 DATE); INSERT INTO T10 SELECT ROWNUM, 'A'||TO_CHAR(ROWNUM)||'Z', 'A'||TO_CHAR(ROWNUM)||'Z', SYSDATE+ROWNUM/10 FROM DUAL CONNECT BY LEVEL<=1000; COMMIT; SET ARRAYSIZE 100
To begin the test, we will enable packet logging in Wireshark, then execute the following in our SQL*Plus session:
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8'; ALTER SESSION SET TRACEFILE_IDENTIFIER = 'AUTOTRACE_STATISTICS_TRACE'; SET AUTOTRACE TRACEONLY STATISTICS SELECT * FROM T10 ORDER BY C1; DISCONNECT ALL;
For my test execution, the following was displayed in SQL*Plus:
1000 rows selected. Statistics --------------------------------------------------- 0 recursive calls 0 db block gets 7 consistent gets 0 physical reads 0 redo size 33470 bytes sent via SQL*Net to client 459 bytes received via SQL*Net from client 11 SQL*Net roundtrips to/from client 1 sorts (memory) 0 sorts (disk) 1000 rows processed
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:
EXEC #5:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=491526459579
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526460488
WAIT #5: nam='SQL*Net message from client' ela= 3932 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526464434
CLOSE #5:c=0,e=3,dep=0,type=1,tim=491526464492
=====================
PARSING IN CURSOR #5 len=40 dep=0 uid=194 oct=3 lid=194 tim=491526464547 hv=3933222116 ad='36cab5360' sqlid='dyk4dprp70d74'
SELECT DECODE('A','A','1','2') FROM DUAL
END OF STMT
PARSE #5:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=491526464546
EXEC #5:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=491526464596
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526464624
FETCH #5:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=491526464651
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
WAIT #5: nam='SQL*Net message from client' ela= 1641 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526466337
CLOSE #5:c=0,e=6,dep=0,type=1,tim=491526466385
=====================
PARSING IN CURSOR #5 len=33 dep=0 uid=194 oct=3 lid=194 tim=491526466449 hv=2185052098 ad='36c33c460' sqlid='bzmk73q13ugy2'
SELECT DISTINCT SID FROM V$MYSTAT
END OF STMT
PARSE #5:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2877173184,tim=491526466448
EXEC #5:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2877173184,tim=491526466521
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526466548
WAIT #5: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=4294967295 new aio limit=129 obj#=-1 tim=491526467243
FETCH #5:c=0,e=705,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=2877173184,tim=491526467269
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='HASH UNIQUE (cr=0 pr=0 pw=0 time=0 us cost=1 size=21 card=1)'
STAT #5 id=2 cnt=588 pid=1 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=821 us cost=0 size=630 card=30)'
STAT #5 id=3 cnt=1 pid=2 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #5: nam='SQL*Net message from client' ela= 2708 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526470036
CLOSE #5:c=0,e=7,dep=0,type=1,tim=491526470085
*** SESSION ID:(1229.11429) 2010-04-25 10:13:17.869
*** SERVICE NAME:(SYS$USERS) 2010-04-25 10:13:17.869
*** MODULE NAME:(SQL*Plus) 2010-04-25 10:13:17.869
*** ACTION NAME:() 2010-04-25 10:13:17.869
=====================
PARSING IN CURSOR #5 len=298 dep=0 uid=194 oct=3 lid=194 tim=491526480837 hv=3566218912 ad='36cdd1b90' sqlid='f7dctcva90bp0'
SELECT STATISTIC# S, NAME FROM SYS.V_$STATNAME WHERE NAME IN ('recursive calls','db block gets','consistent gets','physical reads','redo size','bytes sent via SQL*Net to client','bytes received via SQL*Net from client','SQL*Net roundtrips to/from client','sorts (memory)','sorts (disk)') ORDER BY S
END OF STMT
PARSE #5:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=601351913,tim=491526480836
EXEC #5:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=601351913,tim=491526480950
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526480978
FETCH #5:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=601351913,tim=491526481009
WAIT #5: nam='SQL*Net message from client' ela= 1461 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526482489
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526482574
FETCH #5:c=0,e=248,p=0,cr=0,cu=0,mis=0,r=9,dep=0,og=1,plh=601351913,tim=491526482778
STAT #5 id=1 cnt=10 pid=0 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSD (cr=0 pr=0 pw=0 time=0 us cost=0 size=360 card=10)'
WAIT #5: nam='SQL*Net message from client' ela= 4778 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526487592
*** SESSION ID:(1229.11429) 2010-04-25 10:13:17.869
CLOSE #5:c=0,e=8,dep=0,type=1,tim=491526491403
=====================
PARSING IN CURSOR #5 len=35 dep=0 uid=194 oct=3 lid=194 tim=491526491485 hv=410341182 ad='36c4497b0' sqlid='1y2frjhc7amty'
SELECT
*
FROM
T10
ORDER BY
C1
END OF STMT
PARSE #5:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4242492972,tim=491526491484
EXEC #5:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4242492972,tim=491526491548
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526491574
WAIT #5: nam='Disk file operations I/O' ela= 121 FileOperation=2 fileno=8 filetype=2 obj#=-1 tim=491526491726
FETCH #5:c=0,e=446,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=1,plh=4242492972,tim=491526492037
WAIT #5: nam='SQL*Net message from client' ela= 3403 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526495465
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526495529
FETCH #5:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526495589
WAIT #5: nam='SQL*Net message from client' ela= 3025 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526498633
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526498679
FETCH #5:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526498754
WAIT #5: nam='SQL*Net message from client' ela= 2924 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526501694
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526501739
FETCH #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526501815
WAIT #5: nam='SQL*Net message from client' ela= 2873 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526504704
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526504749
FETCH #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526504825
WAIT #5: nam='SQL*Net message from client' ela= 2952 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526507793
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526507839
FETCH #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526507914
WAIT #5: nam='SQL*Net message from client' ela= 3453 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526511383
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526511433
FETCH #5:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526511536
WAIT #5: nam='SQL*Net message from client' ela= 2857 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526514412
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526514453
FETCH #5:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526514501
WAIT #5: nam='SQL*Net message from client' ela= 2812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526517332
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526517377
FETCH #5:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526517429
WAIT #5: nam='SQL*Net message from client' ela= 2897 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526520366
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526520412
FETCH #5:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526520463
WAIT #5: nam='SQL*Net message from client' ela= 2849 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526523328
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526523374
FETCH #5:c=0,e=67,p=0,cr=0,cu=0,mis=0,r=99,dep=0,og=1,plh=4242492972,tim=491526523435
STAT #5 id=1 cnt=1000 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=7 pr=0 pw=0 time=285 us cost=4 size=31000 card=1000)'
STAT #5 id=2 cnt=1000 pid=1 pos=1 obj=82545 op='TABLE ACCESS FULL T10 (cr=7 pr=0 pw=0 time=249 us cost=3 size=31000 card=1000)'
WAIT #5: nam='SQL*Net message from client' ela= 4630 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526528115
*** SESSION ID:(1229.11429) 2010-04-25 10:13:17.947
XCTEND rlbk=0, rd_only=1, tim=491526563841
=====================
PARSING IN CURSOR #6 len=447 dep=1 uid=0 oct=2 lid=0 tim=491526563926 hv=1097020010 ad='36cc895f8' sqlid='f711myt0q6cma'
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,terminal,action#,returncode, logoff$lread,logoff$pread,logoff$lwrite,logoff$dead, logoff$time,comment$text,spare1,clientid,sessioncpu,proxy$sid,user$guid, instance#,process#,auditid,dbid) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP), :4,:5,:6,:7,:8, :9,:10,:11,:12, cast(SYS_EXTRACT_UTC(systimestamp) as date),:13,:14,:15,:16,:17,:18, :19,:20,:21,:22)
END OF STMT
PARSE #6:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=0,tim=491526563926
EXEC #6:c=0,e=67,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,plh=0,tim=491526564082
STAT #6 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL (cr=1 pr=0 pw=0 time=0 us)'
CLOSE #6:c=0,e=4,dep=1,type=1,tim=491526564123
WAIT #0: nam='log file sync' ela= 33 buffer#=3872 sync scn=1305056145 p3=0 obj#=-1 tim=491526564191
CLOSE #2:c=0,e=6,dep=0,type=0,tim=491526564244
CLOSE #5:c=0,e=3,dep=0,type=0,tim=491526564260
CLOSE #4:c=0,e=4,dep=0,type=0,tim=491526564271
CLOSE #3:c=0,e=9,dep=0,type=0,tim=491526564287
CLOSE #1:c=0,e=3,dep=0,type=0,tim=491526564298
With the help of these articles, 10046 Extended SQL Trace Interpretation and 10046 Extended SQL Trace Interpretation 2, we are able to decode most of the above trace file output that was generated by Oracle Database 11.2.0.1. For example, we see these helpful SQL statement before the SQL statement that we executed:
SELECT DECODE('A','A','1','2') FROM DUAL
SELECT DISTINCT SID FROM V$MYSTAT
SELECT STATISTIC# S, NAME FROM SYS.V_$STATNAME WHERE NAME IN
('recursive calls','db block gets','consistent gets','physical reads','redo size',
'bytes sent via SQL*Net to client','bytes received via SQL*Net from client',
'SQL*Net roundtrips to/from client','sorts (memory)','sorts (disk)') ORDER BY S
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:
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost, terminal,action#,returncode, logoff$lread,logoff$pread,logoff$lwrite,logoff$dead, logoff$time,comment$text,spare1,clientid,sessioncpu,proxy$sid,user$guid, instance#, process#,auditid,dbid) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP), :4,:5,:6,:7,:8, :9,:10,:11,:12, cast(SYS_EXTRACT_UTC(systimestamp) as date), :13,:14,:15,:16,:17,:18, :19,:20,:21,:22)
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:
—
Finally, packet 23 shows the SQL statement that we 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;
I saved the Hex Dump output from Wireshark’s follow stream to a file: NetworkMonitoringExperimentations4-FetchSize.txt (save with a .txt extension). Feel free to confirm that the array fetch size is provided in that byte location.
ARRAYSIZE=10 00000324 00 15 00 00 06 00 00 00 00 00 03 05 3b 05 00 00 ........ ....;... 00000334 00 0a 00 00 00 ..... ... 00000339 00 15 00 00 06 00 00 00 00 00 03 05 3c 05 00 00 ........ ....<... 00000349 00 0a 00 00 00 ..... ... ... ARRAYSIZE=50 00000F13 00 15 00 00 06 00 00 00 00 00 03 05 aa 05 00 00 ........ ........ 00000F23 00 32 00 00 00 .2... ... 00000F28 00 15 00 00 06 00 00 00 00 00 03 05 ab 05 00 00 ........ ........ 00000F38 00 32 00 00 00 .2... ... ... ARRAYSIZE=100 00001472 00 15 00 00 06 00 00 00 00 00 03 05 c9 05 00 00 ........ ........ 00001482 00 64 00 00 00 .d... ... 00001487 00 15 00 00 06 00 00 00 00 00 03 05 ca 05 00 00 ........ ........ 00001497 00 64 00 00 00 .d... ... ... ARRAYSIZE=500 000018FF 00 15 00 00 06 00 00 00 00 00 03 05 de 05 00 00 ........ ........ 0000190F 00 f4 01 00 00 ..... ... 00001914 00 15 00 00 06 00 00 00 00 00 03 05 df 05 00 00 ........ ........ 00001924 00 f4 01 00 00 .....
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?
Charles Hooper's Oracle Notes 
Hi Charles,
The dates and numbers in the packet trace are in the same format you’d find them in a block dump.
For instance, the 7 bytes – 78 6e 05 18 0a 37 18 – represent 2010-05-24 09:54:23 (May 24th).
DBMS_STATS.CONVERT_RAW_VALUE can be used to do the decoding
eg:
declare tmp date; begin dbms_stats.convert_raw_value(hextoraw(replace(upper('78 6e 05 18 08 1f 18'),' ')), tmp); dbms_output.put_line(TO_CHAR(tmp,'YYYY-MM-DD HH24:MI:SS')); end; /Likewise, c2 03 5a is the number 289. The byte before this is the length byte.
Put that together in an example for your trace:
Tim,
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.
My original thought was to experiment with DUMP, something like this:
ALTER SESSION SET NLS_DATE_FORMAT='YYYY-MM-DD HH24:MI:SS'; SELECT TO_DATE('2010-05-24 07:30:23','YYYY-MM-DD HH24:MI:SS') MY_DATE, DUMP(TO_DATE('2010-05-24 07:30:23','YYYY-MM-DD HH24:MI:SS')) MY_DATE_DUMP FROM DUAL; MY_DATE MY_DATE_DUMP ------------------- ---------------------------------- 2010-05-24 07:30:23 Typ=13 Len=8: 218,7,5,24,7,30,23,0This 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.
Hi Charles, that was a quick reply!
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 at
http://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):
CREATE TABLE T1 (C1 DATE); INSERT INTO T1 VALUES (TO_DATE('2010-05-24 07:30:23','YYYY-MM-DD HH24:MI:SS')); ALTER SESSION SET NLS_DATE_FORMAT='YYYY-MM-DD HH24:MI:SS'; SELECT TO_DATE('2010-05-24 07:30:23','YYYY-MM-DD HH24:MI:SS') MY_DATE, DUMP(C1) C1_DUMP, DUMP(TO_DATE('2010-05-24 07:30:23','YYYY-MM-DD HH24:MI:SS')) MY_DATE_DUMP FROM T1; MY_DATE C1_DUMP MY_DATE_DUMP ------------------- ---------------------------------- ---------------------------------- 2010-05-24 07:30:23 Typ=12 Len=7: 120,110,5,24,8,31,24 Typ=13 Len=8: 218,7,5,24,7,30,23,0This is the observation that I would have made with the C1_DUMP:
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.
Hi Charles,
It’s a combination of my copy and paste error and “reading bytes from right to left” that’s causing the trouble – They’re left to right.
’78 6e 05 18 08 1f 18′ is ‘2010-05-24 07:30:23’ (NOT 09:54 as I mistakenly pasted above)
0x78 = 120 = 20 + 100
0x6e = 110 = 10 + 100
ie 0x78 0x6e = 2010
0x05 = May
0x18 = 24
0x08 = 7 + 1
0x1f = 31 = 30 + 1
0x18 = 24 = 23 + 1
Apologies for the copy and paste error and hope this clears things up.
Hi Charles,
That is a nice post.
I’m glad you found the sql-only version of translating raw values of oracle data into human readable format helpful and thanks for the link.
I updated the script later, in light of lots of help by others, to handle timestamps too. The update can be found at http://mwidlake.wordpress.com/2010/02/24/update-to-decoding-high-and-low-values/
Thanks,
Martin
Martin,
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).