Introduction
This blog post is inspired by a question from an attendee of Sigrid Keydana's DOAG 2015 conference session called "Raising the fetchsize, good or bad? Exploring memory management in Oracle JDBC 12c". Basically it was a question about what the wait event "SQL*Net more data to client" represents and what it really measures. In general you may use the following steps, if you don't know what a particular wait event means:
- Check the official Oracle documentation or My Oracle Support for an explanation
- Google for trustful sources / websites
- Do your own research
So let's do this procedure for wait event "SQL*Net more data to client" as an example:
- Official Oracle documentation "SQL*Net more data to client": "The server process is sending more data/messages to the client. The previous operation to the client was also a send. Wait Time: The actual time it took for the send to complete"
- Google for trustful sources / websites, e.g. blog post "SQL*Net message to client vs SQL*Net more data to client" by Tanel Poder: "I’ll reiterate that both SQL*Net message to client and SQL*Net more data to client waits only record the time it took to write the return data from Oracle’s userland SDU buffer to OS kernel-land TCP socket buffer. Thus the wait times of only microseconds. Thanks to that, all of the time a TCP packet spent flying towards the client is actually accounted in SQL*Net message from client wait statistic."
Do you see the slightly but important difference between the official documentation and Tanel Poder's blog content? The Oracle documentation states that it measures the time it took for the send to complete, but Tanel says that it only measures the time to write the return data from Oracle’s userland SDU buffer to OS kernel-land TCP socket buffer. In such cases i would trust Tanel much more, but let's verify this on our own as we would need to do it anyway, if we do not find any trustful source via Google. The following approach can be applied to any wait event, if you want to know what it really represents.
Basics of Oracle's code instrumentation
I will not repeat all of the basics here as there is already a great source of information about this in the internet, but i am referring to Cary Millsap's "The Method R Guide to MASTERING ORACLE TRACE DATA" to get a basic understanding of what we are talking about.
Database call instrumentation
System call instrumentation
Basically Oracle's code instrumentation is very simple and straight forward, but we need to know where the measurement starts and where it exactly ends in the Oracle code, if we want to get an understanding of the measured time of Oracle functions and system calls. For the beginning the only thing we need to know is the following:
- Oracle function kslwtbctx represents the start of a wait event
- Oracle function kslwtbctx calls the function kskthbwt to get/store the corresponding wait event (number)
- Oracle function kslwtectx represents the end of a wait event
- Oracle function kslwtectx calls the function kskthewt to get/store the corresponding wait event (number)
Let's see what Oracle really measures in case of wait event "SQL*Net more data to client".
Deep dive into Oracle's wait interface for wait event "SQL*Net more data to client" with DTrace
The following demo was run on an Oracle database (12.1.0.2) on Solaris 11.2 (SunOS SOL 5.11 11.2 i86pc i386 i86pc).
Create the base table, data set and SDU configuration
SQL> create table TEST (a varchar2(3000));
SQL> insert into TEST values (rpad('x',3000,'x'));
SQL> commit;
shell> cat $TNS_ADMIN/sqlnet.ora
DEFAULT_SDU_SIZE=2048
Wait event verification
SQL> select EVENT#, EVENT_ID, NAME from V$EVENT_NAME where NAME in
('SQL*Net more data to client','SQL*Net message to client','SQL*Net message from client');
EVENT# EVENT_ID NAME
---------- ---------- ----------------------------------------------------------------
384 2067390145 SQL*Net message to client
386 554161347 SQL*Net more data to client
388 1421975091 SQL*Net message from client
SQL> select * from TEST;
Network package dumps
At first let's have a look at the SQL*Net trace on server side (parameter TRACE_LEVEL_SERVER = SUPPORT in sqlnet.ora) to verify the network packages and get an idea what we need to look at in the Oracle code.
...
2015-12-09 18:51:45.874331 : nsbasic_brc:entry: oln/tot=0
2015-12-09 18:51:45.874378 : nttfprd:entry
2015-12-09 18:52:04.455082 : nttfprd:socket 17 had bytes read=275
2015-12-09 18:52:04.455311 : nttfprd:exit
2015-12-09 18:52:04.455358 : nsbasic_brc:type=6, plen=275
2015-12-09 18:52:04.455428 : nsbasic_brc:what=1, tot =275
2015-12-09 18:52:04.455475 : nsbasic_brc:packet dump
2015-12-09 18:52:04.455519 : nsbasic_brc:01 13 00 00 06 00 00 00 |........|
…
2015-12-09 18:52:04.456573 : nsbasic_brc:00 00 00 00 12 73 65 6C |.....sel|
2015-12-09 18:52:04.456612 : nsbasic_brc:65 63 74 20 2A 20 66 72 |ect.*.fr|
2015-12-09 18:52:04.456653 : nsbasic_brc:6F 6D 20 54 45 53 54 01 |om.TEST.|
…
2015-12-09 18:52:04.456973 : nsbasic_brc:exit: oln=0, dln=265, tot=275, rc=0
2015-12-09 18:52:04.457022 : nioqrc:exit
2015-12-09 18:52:04.457377 : nioqsn:entry
2015-12-09 18:52:04.457423 : nioqsn:exit
2015-12-09 18:52:04.457583 : nioqsn:entry
2015-12-09 18:52:04.457656 : nsbasic_bsd:entry
2015-12-09 18:52:04.457694 : nsbasic_bsd:tot=0, plen=1967.
2015-12-09 18:52:04.457733 : nttfpwr:entry
2015-12-09 18:52:04.457904 : nttfpwr:socket 17 had bytes written=1967
2015-12-09 18:52:04.457954 : nttfpwr:exit
2015-12-09 18:52:04.457996 : nsbasic_bsd:packet dump
…
2015-12-09 18:52:04.458909 : nsbasic_bsd:0B 78 78 78 78 78 78 78 |.xxxxxxx|
2015-12-09 18:52:04.458946 : nsbasic_bsd:78 78 78 78 78 78 78 78 |xxxxxxxx|
2015-12-09 18:52:04.458982 : nsbasic_bsd:78 78 78 78 78 78 78 78 |xxxxxxxx|
…
2015-12-09 18:52:04.468161 : nsbasic_bsd:exit (0)
2015-12-09 18:52:04.468201 : nioqsn:exit
2015-12-09 18:52:04.468312 : nioqrc:entry
2015-12-09 18:52:04.468356 : nsbasic_bsd:entry
2015-12-09 18:52:04.468397 : nsbasic_bsd:tot=0, plen=1317.
2015-12-09 18:52:04.468443 : nttfpwr:entry
2015-12-09 18:52:04.468554 : nttfpwr:socket 17 had bytes written=1317
2015-12-09 18:52:04.468601 : nttfpwr:exit
2015-12-09 18:52:04.468642 : nsbasic_bsd:packet dump
2015-12-09 18:52:04.468718 : nsbasic_bsd:05 25 00 00 06 00 00 00 |.%......|
2015-12-09 18:52:04.468765 : nsbasic_bsd:00 00 78 78 78 78 78 78 |..xxxxxx|
2015-12-09 18:52:04.468805 : nsbasic_bsd:78 78 78 78 78 78 78 78 |xxxxxxxx|
2015-12-09 18:52:04.468846 : nsbasic_bsd:78 78 78 78 78 78 78 78 |xxxxxxxx|
…
2015-12-09 18:52:04.475756 : nsbasic_bsd:exit (0)
2015-12-09 18:52:04.475799 : nsbasic_brc:entry: oln/tot=0
2015-12-09 18:52:04.475840 : nttfprd:entry
2015-12-09 18:52:04.475891 : nttfprd:socket 17 had bytes read=21
2015-12-09 18:52:04.475931 : nttfprd:exit
2015-12-09 18:52:04.475971 : nsbasic_brc:type=6, plen=21
2015-12-09 18:52:04.476011 : nsbasic_brc:what=1, tot =21
2015-12-09 18:52:04.476050 : nsbasic_brc:packet dump
2015-12-09 18:52:04.476091 : nsbasic_brc:00 15 00 00 06 00 00 00 |........|
2015-12-09 18:52:04.476130 : nsbasic_brc:00 00 03 05 1D 01 00 00 |........|
2015-12-09 18:52:04.476181 : nsbasic_brc:00 0F 00 00 00 |..... |
2015-12-09 18:52:04.476228 : nsbasic_brc:exit: oln=0, dln=11, tot=21, rc=0
2015-12-09 18:52:04.476269 : nioqrc:exit
2015-12-09 18:52:04.476441 : nioqsn:entry
2015-12-09 18:52:04.476488 : nioqsn:exit
…
Oracle needs two SDU buffers (of 2048 bytes) to send my table data (a lot of x characters) to the client. The first SDU buffer is filled up to 1967 bytes and written to the network socket and the second one is filled up to 1317 bytes with the rest of data and also written to the network socket. Let's crosscheck how Oracle accounts this in the Oracle wait interface.
DTracing the wait interface
I used a slightly modified version of Brendan Gregg's DTrace wrapper script (print decimal instead of hex values) called dapptrace. The symbol "->" indicates the entry into a C function and the symbol "<-" indicates the return from a C function. I marked the previously mentioned code instrumentation parts as red and the code that is actually measured by this particular wait event as orange.
shell> ./dapptrace.sh -UFp 1267
… -> oracle:kslwtbctx(-139639050531264, 1, 0)
-> libc.so.1:gethrtime%hrt(6966823560, 0, 255)
<- libc.so.1:gethrtime%hrt = 256
-> oracle:kskthbwt(0, 3268360526, 386)
-> oracle:kgskbwt(-139639066914912, 7241882880, 0)
-> oracle:kstmgethighresustick(-139639066914912, -139639085284392, 7025938216)
<- oracle:kstmgethighresustick = 117
-> oracle:kgskdecr(-139639066914912, 1, 7025943768)
<- oracle:kgskdecr = 311
-> oracle:kgskupdbalance(-139639066914912, 7241882880, 0)
-> oracle:slcpums(-139639050532496, 7241882880, 0)
-> libc.so.1:_lwp_info(-139639050533200, 7241882880, 0)
<- libc.so.1:_lwp_info = 27
<- oracle:slcpums = 141
-> oracle:ksklheld(60507156, 456459, -139639085284392)
<- oracle:ksklheld = 109
<- oracle:kgskupdbalance = 325
-> oracle:kgskrunnextint(-139639066914912, 7241882880, 0)
<- oracle:kgskrunnextint = 1736
<- oracle:kgskbwt = 937
-> oracle:ksdhng_cache_scpd_ver_get(0, 7241882880, 0)
<- oracle:ksdhng_cache_scpd_ver_get = 26
-> oracle:ksdhng_cache_scpd_ver_get(1, 7241882880, 0)
<- oracle:ksdhng_cache_scpd_ver_get = 26
<- oracle:kskthbwt = 526
-> libc.so.1:memcpy(7260698720, -139639050531160, 48)
-> oracle:kslwt_start_snapshot(7260698616, 7260698616, 1)
<- oracle:kslwt_start_snapshot = 266
<- oracle:kslwtbctx = 1321
-> oracle:nioqsn(-139639066788456, 0, 6402865975)
-> libc.so.1:memcpy(-139639084441095, 6402865975, 20)
-> oracle:nsbsend(-139639084713376, -139639084713048, 1)
-> oracle:nsbasic_bsd(-139639084713376, -139639084713048, 1)
-> oracle:nttfpwr(-139639084639792, -139639084443042, -139639050534232)
-> libc.so.1:write(17, -139639084443042, 1967)
-> libc.so.1:__write(17, -139639084443042, 1967)
<- libc.so.1:__write = 22
<- libc.so.1:write = 252
<- oracle:nttfpwr = 277
<- oracle:nsbasic_bsd = 525
-> libc.so.1:memcpy(-139639084443032, 6402865995, 235)
<- oracle:nioqsn = 550
-> oracle:kslwtectx(-139639050531264, 6402865995, 6402866230)
-> libc.so.1:gethrtime%hrt(-139639050531264, 6402865995, 6402866230)
<- libc.so.1:gethrtime%hrt = 256
-> oracle:kslwt_end_snapshot(7260698616, 7260698616, 1)
<- oracle:kslwt_end_snapshot = 586
-> oracle:kslwt_update_stats_int(7260698616, 7260698616, 30)
-> oracle:kews_update_wait_time(7, 1652, -139639066773184)
<- oracle:kews_update_wait_time = 45
<- oracle:kslwt_update_stats_int = 733
-> oracle:kskthewt(3268362178, 386, 10)
-> oracle:kgskewt(-139639066914912, 7241882880, 7241882880)
<- oracle:kgskewt = 87
-> oracle:kgskewtint(-139639066914912, 7241882880, 7241882880)
-> oracle:kstmgethighresustick(-139639066914912, 7241882992, 1610635576)
<- oracle:kstmgethighresustick = 117
-> oracle:kgskmodruncnt(-139639066914912, 7241882880, 0)
-> oracle:ksklheld(-139639066914912, 1, 0)
<- oracle:ksklheld = 109
<- oracle:kgskmodruncnt = 435
-> oracle:slcpums(-139639050532160, 2, 4)
-> libc.so.1:_lwp_info(-139639050532912, 2, 4)
<- libc.so.1:_lwp_info = 27
<- oracle:slcpums = 141
<- oracle:kgskewtint = 972
<- oracle:kskthewt = 636
<- oracle:kslwtectx = 994
…
-> oracle:kslwtbctx(-139639050487328, 33, 11)
-> libc.so.1:gethrtime%hrt(6966823560, 0, 255)
<- libc.so.1:gethrtime%hrt = 256
-> oracle:kskthbwt(0, 3268369142, 388)
-> oracle:kgskbwt(-139639066914912, 7241882880, 0)
-> oracle:kstmgethighresustick(-139639066914912, -139639085284392, 7025938216)
<- oracle:kstmgethighresustick = 117
-> oracle:kgskdecr(-139639066914912, 1, 7025943768)
<- oracle:kgskdecr = 311
-> oracle:kgskupdbalance(-139639066914912, 7241882880, 0)
-> oracle:slcpums(-139639050488560, 7241882880, 0)
-> libc.so.1:_lwp_info(-139639050489264, 7241882880, 0)
<- libc.so.1:_lwp_info = 27
<- oracle:slcpums = 141
-> oracle:ksklheld(60630990, 464768, -139639085284392)
<- oracle:ksklheld = 109
<- oracle:kgskupdbalance = 325
-> oracle:kgskrunnextint(-139639066914912, 7241882880, 0)
<- oracle:kgskrunnextint = 1736
<- oracle:kgskbwt = 937
-> oracle:ksdhng_cache_scpd_ver_get(0, 7241882880, 0)
<- oracle:ksdhng_cache_scpd_ver_get = 26
-> oracle:ksdhng_cache_scpd_ver_get(1, 7241882880, 0)
<- oracle:ksdhng_cache_scpd_ver_get = 26
<- oracle:kskthbwt = 526
-> libc.so.1:memcpy(7260698720, -139639050487224, 48)
-> oracle:kslwt_start_snapshot(7260698616, 7260698616, 1)
<- oracle:kslwt_start_snapshot = 266
<- oracle:kslwtbctx = 1321
-> oracle:nioqrc(-139639066788456, 0, -139639050486724)
-> oracle:nsbsend(-139639084713376, -139639084713048, 1)
-> oracle:nsbasic_bsd(-139639084713376, -139639084713048, 1)
-> oracle:nttfpwr(-139639084639792, -139639084443042, -139639050492280)
-> libc.so.1:write(17, -139639084443042, 1317)
-> libc.so.1:__write(17, -139639084443042, 1317)
<- libc.so.1:__write = 22
<- libc.so.1:write = 252
<- oracle:nttfpwr = 277
<- oracle:nsbasic_bsd = 525
-> oracle:nsbrecv(-139639084713376, -139639084712880, -139639050491220)
-> oracle:nsbasic_brc(-139639084713376, -139639084712880, -139639050491220)
-> oracle:nttfprd(-139639084639792, -139639084445250, 2064)
-> libc.so.1:read(17, -139639084445250, 2064)
-> libc.so.1:__read(17, -139639084445250, 2064)
<- libc.so.1:__read = 22
<- libc.so.1:read = 252
<- oracle:nttfprd = 381
<- oracle:nsbasic_brc = 837
-> libc.so.1:memcpy(-139639050486724, -139639084445240, 1)
<- oracle:nioqrc = 919
-> oracle:kslwtectx(-139639050487328, -139639084445240, -139639084445239)
-> libc.so.1:gethrtime%hrt(-139639050487328, -139639084445240, -139639084445239)
<- libc.so.1:gethrtime%hrt = 256
-> oracle:kslwt_end_snapshot(7260698616, 7260698616, 1)
<- oracle:kslwt_end_snapshot = 586
-> oracle:kslwt_update_stats_int(7260698616, 7260698616, 30)
-> oracle:kews_update_wait_time(6, 1773, -139639066773184)
<- oracle:kews_update_wait_time = 45
<- oracle:kslwt_update_stats_int = 733
-> oracle:kskthewt(3268370915, 388, 10)
-> oracle:kgskewt(-139639066914912, 7241882880, 7241882880)
<- oracle:kgskewt = 87
-> oracle:kgskewtint(-139639066914912, 7241882880, 7241882880)
-> oracle:kstmgethighresustick(-139639066914912, 7241882992, 1610635576)
<- oracle:kstmgethighresustick = 117
-> oracle:kgskmodruncnt(-139639066914912, 7241882880, 0)
-> oracle:ksklheld(-139639066914912, 1, 0)
<- oracle:ksklheld = 109
<- oracle:kgskmodruncnt = 435
-> oracle:slcpums(-139639050488224, 2, 4)
-> libc.so.1:_lwp_info(-139639050488976, 2, 4)
<- libc.so.1:_lwp_info = 27
<- oracle:slcpums = 141
<- oracle:kgskewtint = 972
<- oracle:kskthewt = 636
<- oracle:kslwtectx = 994
…
After dtracing the Oracle process it becomes obvious that Oracle instrumented the first SDU buffer system call write (+ the calling Oracle functions) of 1967 bytes as "SQL*Net more data to client" (wait event number 386) in this case. The Solaris write() system call is defined as the following "If fildes refers to a socket, write() is equivalent to send(3SOCKET) with no flags set", but this is just buffered and does not wait until it gets an acknowledge from the peer (afaik). The second SDU buffer system call write (+ the calling Oracle functions) of 1317 bytes is accounted as "SQL*Net message from client" (wait event number 388), but if you look closely Oracle also accounts the system call read from this socket as "SQL*Net message from client". So basically it represents the wait time to transfer the data until it gets a message back from the client.
You also can correlate each C function flow with the SQL*Net trace as the function names are also printed in the trace file - just as an example (function nttfprd() calls system call read()) .
SQL*Net trace
…
2015-12-09 18:52:04.475840 : nttfprd:entry
2015-12-09 18:52:04.475891 : nttfprd:socket 17 had bytes read=21
2015-12-09 18:52:04.475931 : nttfprd:exit
…
DTrace
…
-> oracle:nttfprd(-139639084639792, -139639084445250, 2064)
-> libc.so.1:read(17, -139639084445250, 2064)
-> libc.so.1:__read(17, -139639084445250, 2064)
<- libc.so.1:__read = 22
<- libc.so.1:read = 252
<- oracle:nttfprd = 381
…
Extended SQL trace and truss
I run an extended SQL trace (and truss on the process) as a last crosscheck to verify this research / findings.
shell> truss -p 1267
…
write(8, " P A R S E # 1 8 4 4 6".., 105) = 105
write(8, " E X E C # 1 8 4 4 6 6".., 103) = 103
write(8, " W A I T # 1 8 4 4 6 6".., 126) = 126
write(17, "07AF\0\006\0\0\0\0\01017".., 1967) = 1967
write(8, " W A I T # 1 8 4 4 6 6".., 131) = 131
write(8, " F E T C H # 1 8 4 4 6".., 106) = 106
write(17, "051F\0\006\0\0\0\0\0 x x".., 1317) = 1317
read(17, "\015\0\006\0\0\0\0\00305".., 2064) = 21
write(8, " W A I T # 1 8 4 4 6 6".., 128) = 128
write(8, " F E T C H # 1 8 4 4 6".., 104) = 104
write(8, " S T A T # 1 8 4 4 6 6".., 140) = 140
write(8, " W A I T # 1 8 4 4 6 6".., 126) = 126
write(17, "\0 f\0\006\0\0\0\0\00401".., 102) = 102
read(17, 0xFFFF80FFBDF991BE, 2064) (sleeping...)
…
This cross-check fits to everything before (aside from the byte difference of 1967 vs. 2191 bytes in the wait interface, which i can not explain), but what becomes obvious is that the wait event "SQL*Net message to client" also does not really send anything via network to the client (no corresponding write() system call) in this case.
Summary
The intention of this blog post was to demonstrate that you can get detailed insights into Oracle's code instrumentation, if you run DTrace on a process and check what is in-between the function flow of C function kslwtbctx and C function kslwtectx. This approach can be adapted to any wait event and may get very interesting in case of CPU driven waits (e.g. mutexes / latches, etc.) or just for educational purpose.
If you have any further questions - please feel free to ask or get in contact directly, if you need assistance by troubleshooting Oracle database (performance) issues. You can also follow or drop me a note on Twitter of course.
- SAP Managed Tags:
