I was asked some time ago what the Oracle database event ‘TCP socket (KGAS)’ means. This blogpost is a deep dive into what this event times in Oracle database 12.1.0.2.180717.
This event is not normally seen, only when TCP connections are initiated from the database using packages like UTL_TCP, UTL_SMTP and the one used in this article, UTL_HTTP.
A very basic explanation is this event times the time that a database foreground session spends on TCP connection management and communicating over TCP, excluding client and database link (sqlnet) networking. If you trace the system calls, you see that mostly that is working with a (network) socket. Part of the code in the oracle database that is managing that, sits in the kernel code layer kgas, kernel generic (of which I am quite sure, and then my guess:) asynchronous services, which explains the naming of the event.
This is what the Oracle online manual (https://docs.oracle.com/database/121/REFRN/GUID-203ACA60-9912-4493-9B79-EA4CDE89A78D.htm#REFRN00642 – Oracle is notorious for breaking links) says about ‘TCP socket (KGAS)’:
C.3.157 TCP Socket (KGAS)
A session is waiting for an external host to provide requested data over a network socket. The time that this wait event tracks does not indicate a problem, and even a long wait time is not a reason to contact Oracle Support. It naturally takes time for data to flow between hosts over a network, and for the remote aspect of an application to process any request made to it. An application that communicates with a remote host must wait until the data it will read has arrived. In addition, on Microsoft Windows, a separate thread monitors the arrival of traffic. This thread spends most of its life in waits tracked by the TCP Socket (KGAS) wait event.
Wait Time: The total elapsed time for the network connection to be established or for data to arrive from over the network
Parameter Description
P0 For Oracle internal use only. Values 8, 9, and 10 occur within the special thread present on Microsoft Windows; other P0 values occur in normal user sessions.
P1 For Oracle internal use only
Overall, the basic explanation that Oracle provides is mostly correct. I think the text saying to not contact Oracle support is not relevant, but maybe there is a need to relieve Oracle support. In my tests, I found that the full TCP connection lifecycle (creation, usage and removal) is put under this event, for which the text seems to emphasise on waiting for a remote host, which would be the most logical culprit for wait times, but other issues could lead to wait times additionally. This means the wait event itself is not explaining what it is showing, outside of TCP connection management.
The wait time explanation is nearly complete. If it would say something like ‘all TCP connection management and usage’ it would have fully covered it, it now excludes disconnecting and sending, because it explicitly mentions creating the connecting and receiving (waiting for data).
I do not understand what is meant with P0 and P1. I think it is p1 and p2 of the wait event, but naming it P0 and P1 is weird. When looking at the explanation it reads to me ‘we do not wish to explain anything to you’.
So, that means I am going to find this out myself….
If you are interested in this, or do want to write articles like this too, I urge you to replay this on your own system.
First of all, create a small setup which you can use to actually execute UTL_HTTP. The example essentially is taken from father of code examples, Tim Hall/Oracle base. Thank you Tim!
First setup the database to allow a user (in my case ‘ts’) to create the objects and use the network:
grant create sequence to ts;
grant create procedure to ts;
grant create table to ts;
grant alter session to ts;
begin
dbms_network_acl_admin.create_acl (
acl => 'anything.xml',
description => 'allow anything',
principal => 'TS',
is_grant => true,
privilege => 'connect'
);
end;
begin
dbms_network_acl_admin.assign_acl (
acl => 'anything.xml',
host => '*'
);
end;
Then connect as the actual user (ts), and create the objects and the procedure that uses UTL_HTTP:
drop table http_clob_test;
create table http_clob_test (
id number(10),
url varchar2(255),
data clob,
constraint http_clob_test_pk primary key (id)
);
drop sequence http_clob_test_seq;
create sequence http_clob_test_seq;
CREATE OR REPLACE PROCEDURE load_html_from_url (p_url IN VARCHAR2) AS
-- examples by tim hall
-- https://oracle-base.com/articles/misc/retrieving-html-and-binaries-into-tables-over-http
l_http_request UTL_HTTP.req;
l_http_response UTL_HTTP.resp;
l_clob CLOB;
l_text VARCHAR2(32767);
BEGIN
DBMS_LOB.createtemporary(l_clob, FALSE);
-- Make a HTTP request and get the response.
l_http_request := UTL_HTTP.begin_request(p_url);
l_http_response := UTL_HTTP.get_response(l_http_request);
-- Copy the response into the CLOB.
BEGIN
LOOP
UTL_HTTP.read_text(l_http_response, l_text, 32766);
DBMS_LOB.writeappend (l_clob, LENGTH(l_text), l_text);
END LOOP;
EXCEPTION
WHEN UTL_HTTP.end_of_body THEN
UTL_HTTP.end_response(l_http_response);
END;
-- Insert the data into the table.
INSERT INTO http_clob_test (id, url, data)
VALUES (http_clob_test_seq.NEXTVAL, p_url, l_clob);
-- Relase the resources associated with the temporary LOB.
DBMS_LOB.freetemporary(l_clob);
EXCEPTION
WHEN OTHERS THEN
UTL_HTTP.end_response(l_http_response);
DBMS_LOB.freetemporary(l_clob);
RAISE;
END load_html_from_url;
/
The first thing to do is turn on sql_trace at level 8 to include waits:
set serverout on
alter session set events 'sql_trace level 8';
exec load_html_from_url('http://orafun.info/');
alter session set events 'sql_trace off';
If you look at the relevant piece, which means where it shows the wait events, it looks like this:
WAIT #139864521752120: nam='TCP Socket (KGAS)' ela= 128265 =2 =0 =0 obj#=662 tim=86395107497
WAIT #139864521752120: nam='TCP Socket (KGAS)' ela= 395 =5 =0 =0 obj#=662 tim=86395110191
WAIT #139864521752120: nam='TCP Socket (KGAS)' ela= 150 =6 =0 =0 obj#=662 tim=86395111115
WAIT #139864521752120: nam='TCP Socket (KGAS)' ela= 131998 =6 =0 =0 obj#=662 tim=86395243764
WAIT #139864521752120: nam='TCP Socket (KGAS)' ela= 269 =4 =0 =0 obj#=662 tim=86395245182
WAIT #139864521752120: nam='direct path write temp' ela= 4137 file number=201 first dba=257795 block cnt=1 obj#=662 tim=86395250494
WAIT #139864521752120: nam='TCP Socket (KGAS)' ela= 352 =3 =2 =0 obj#=662 tim=86395251294
What is shown here is some quite spectacular differences in elapsed time. Also, the only way to understand what is actually done flagged as ‘TCP Socket (KGAS)’ is the value following ‘ela’, which is the event p1 value.
The pattern is:
- 2
- 5
- 6
- 6
- 4
- 3
It’s relatively simple to guess what a few of these are:
- 2 - connect
- 5 - send
- 6 - \
- 6 - | receiving ?
- 4 - /
- 3 - close
But if you include the timing, there must be more into play:
- 2 - ela= 128265 connect
- 5 - ela= 395 send
- 6 - ela= 150 \
- 6 - ela= 131998 | receiving ?
- 4 - ela= 14 /
- 3 - ela= 177 close
2/connect: In order to build up a connection, a tcp connection needs to be created and established. That takes some time.
5/send: Sending from the perspective of a userland process is writing into a socket, which will get send by the operating system independently. This means sending from a userland process normally takes relative little time, because it’s not waiting for actually sending it.
6,4/receive: At this time, this doesn’t make sense to me.
3/close: Closing for a userland process is a simple, swift task. The operating system will keep the port open for some time, etc. but this is not visible for the user land application.
Let’s pull an old trick out of the hat: use strace (system call tracing) with an emphasis on writing on an oracle session that has SQL trace with waits enabled set. This will show the system calls executed, and show exactly when the oracle engine ends a wait, so we can reasonably well establish a relation between wait events and system calls. I say “reasonably well”, because we can’t see when Oracle truly started timing the wait event (kslwtbctx), only the output to trace file as part of ending the wait event (kslwtectx).
The way I done it, is using the command ‘strace -e write=all -p 18513 -o utl_http_test.txt’. Obviously 18513 is the process ID of the database foreground process. The results of the strace are in utl_http_test.txt.
Now open utl_http_test.txt and search for KGAS. The full output is way too much text, let me show some of the output which I think is noteworthy. Again: this is selective, partial output.
I do maintain the order in which the calls are visible.
1. TCP Socket (KGAS) p1=2, earlier annotated as ‘connect’
-- try to find a socket that has been created by nscd (name server caching deamon)
-- two times?
--
socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 9
connect(9, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(9) = 0
socket(AF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 9
connect(9, {sa_family=AF_LOCAL, sun_path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(9) = 0
--
-- obtain file status of resolv.conf (hostname resolving configuration file)
--
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=93, ...}) = 0
--
-- open and read host.conf (another hostname resolving configuration file)
--
open("/etc/host.conf", O_RDONLY|O_CLOEXEC) = 9
fstat(9, {st_mode=S_IFREG|0644, st_size=9, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34bf377000
read(9, "multi on\n", 4096) = 9
read(9, "", 4096) = 0
close(9) = 0
--
-- open and read resolv.conf (hostname resolving configuration)
--
open("/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 9
fstat(9, {st_mode=S_IFREG|0644, st_size=93, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34bf377000
read(9, "# Generated by NetworkManager\nse"..., 4096) = 93
read(9, "", 4096) = 0
close(9) = 0
--
-- open /etc/hosts (ip address to hostname mapping locally)
--
open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 9
fstat(9, {st_mode=S_IFREG|0644, st_size=200, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34bf377000
read(9, "127.0.0.1 localhost localhost."..., 4096) = 200
read(9, "", 4096) = 0
close(9)
--
-- at this point two dynamic loadable libraries are read: libnss_dns.so.2 and libresolv.so.2
--
-- this is the DNS lookup of orafun.info
-- again, this is done twice, just like the use of /var/run/nscd/socket above?
--
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 9
connect(9, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.2.3")}, 16) = 0
poll([{fd=9, events=POLLOUT}], 1, 0) = 1 ([{fd=9, revents=POLLOUT}])
sendto(9, "=#\1\0\0\1\0\0\0\0\0\0\6orafun\4info\0\0\1\0\1", 29, MSG_NOSIGNAL, NULL, 0) = 29
| 00000 3d 23 01 00 00 01 00 00 00 00 00 00 06 6f 72 61 =#...........ora |
| 00010 66 75 6e 04 69 6e 66 6f 00 00 01 00 01 fun.info..... |
poll([{fd=9, events=POLLIN}], 1, 5000) = 1 ([{fd=9, revents=POLLIN}])
ioctl(9, FIONREAD, [45]) = 0
recvfrom(9, "=#\201\200\0\1\0\1\0\0\0\0\6orafun\4info\0\0\1\0\1\300\f\0"..., 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.2.3")}, [16]) = 45
close(9) = 0
socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 9
connect(9, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.2.3")}, 16) = 0
poll([{fd=9, events=POLLOUT}], 1, 4971) = 1 ([{fd=9, revents=POLLOUT}])
sendto(9, "o=\1\0\0\1\0\0\0\0\0\0\6orafun\4info\0\0\34\0\1", 29, MSG_NOSIGNAL, NULL, 0) = 29
| 00000 6f 3d 01 00 00 01 00 00 00 00 00 00 06 6f 72 61 o=...........ora |
| 00010 66 75 6e 04 69 6e 66 6f 00 00 1c 00 01 fun.info..... |
poll([{fd=9, events=POLLIN}], 1, 4970) = 1 ([{fd=9, revents=POLLIN}])
ioctl(9, FIONREAD, [109]) = 0
recvfrom(9, "o=\201\200\0\1\0\0\0\1\0\0\6orafun\4info\0\0\34\0\1\300\f\0"..., 65536, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.2.3")}, [16]) = 109
close(9) = 0
--
-- an epoll is created at file descriptor 9 (epoll: I/O event notification facility)
--
epoll_create(82) = 9
fcntl(9, F_SETFD, FD_CLOEXEC) = 0
--
-- an IPV6 socket is created at file descriptor 11,
-- bound to the IPV6 equivalent of localhost (::1),
-- destination port 0, source port 63257,
-- and is NOT connected.
--
socket(AF_INET6, SOCK_DGRAM, IPPROTO_IP) = 11
bind(11, {sa_family=AF_INET6, sin6_port=htons(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = 0
getsockname(11, {sa_family=AF_INET6, sin6_port=htons(63257), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
getpeername(11, 0x7ffdea6ba0f8, 0x7ffdea6ba1c8) = -1 ENOTCONN (Transport endpoint is not connected)
getsockopt(11, SOL_SOCKET, SO_SNDBUF, [262144], [4]) = 0
getsockopt(11, SOL_SOCKET, SO_RCVBUF, [262144], [4]) = 0
fcntl(11, F_SETFD, FD_CLOEXEC) = 0
fcntl(11, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
--
-- File descriptor 11 is added to the epoll at file descriptor 9.
--
epoll_ctl(9, EPOLL_CTL_ADD, 11, {EPOLLIN, {u32=3110993336, u64=139864426020280}}) = 0
--
-- A connection is created to the true destination (orafun.info/18.218.92.122).
-- This connection gets file descriptor 12.
-- Destination port 80 (http), source port 11751.
--
socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 12
fcntl(12, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(12, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("18.218.92.122")}, 16) = -1 EINPROGRESS (Operation now in progress)
times(NULL) = 438106227
mmap(NULL, 786432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34b959b000
poll([{fd=12, events=POLLOUT}], 1, 60000) = 1 ([{fd=12, revents=POLLOUT}])
getsockopt(12, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
fcntl(12, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK)
fcntl(12, F_SETFL, O_RDWR) = 0
getsockname(12, {sa_family=AF_INET, sin_port=htons(11751), sin_addr=inet_addr("10.0.2.15")}, [16]) = 0
getsockopt(12, SOL_SOCKET, SO_SNDBUF, [87040], [4]) = 0
getsockopt(12, SOL_SOCKET, SO_RCVBUF, [374400], [4]) = 0
setsockopt(12, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(12, F_SETFD, FD_CLOEXEC) = 0
--
-- And this is the wait event written by the process: TCP Socket (KGAS), p1=2
--
write(7, "WAIT #139864521752120: nam='TCP "..., 95) = 95
| 00000 57 41 49 54 20 23 31 33 39 38 36 34 35 32 31 37 WAIT #1398645217 |
| 00010 35 32 31 32 30 3a 20 6e 61 6d 3d 27 54 43 50 20 52120: nam='TCP |
| 00020 53 6f 63 6b 65 74 20 28 4b 47 41 53 29 27 20 65 Socket (KGAS)' e |
| 00030 6c 61 3d 20 31 32 38 32 36 35 20 20 3d 32 20 20 la= 128265 =2 |
| 00040 3d 30 20 20 3d 30 20 6f 62 6a 23 3d 36 36 32 20 =0 =0 obj#=662 |
| 00050 74 69 6d 3d 38 36 33 39 35 31 30 37 34 39 37 tim=86395107497 |
So yes, I am not sure if all of this is in the wait event, but there is a lot of stuff happening to build a connection to the remote server.
In order to find out why the lookup which is tried via the NSCD socket at the beginning, and later via DNS, is done twice, I ran the same procedure again and used tcpdump to look at the actual network traffic. This explained a lot:
# tcpdump -n host 10.0.2.3 and port 53
09:14:02.923389 IP 10.0.2.15.16819 > 10.0.2.3.domain: 15651+ A? orafun.info. (29)
09:14:02.948791 IP 10.0.2.3.domain > 10.0.2.15.16819: 15651 1/0/0 A 18.218.92.122 (45)
09:14:02.952304 IP 10.0.2.15.54590 > 10.0.2.3.domain: 28477+ AAAA? orafun.info. (29)
09:14:02.979534 IP 10.0.2.3.domain > 10.0.2.15.54590: 28477 0/1/0 (109)
In other words: first a DNS A record is requested (TCPv4 DNS name lookup), which results in the IPv4 ip address, then a DNS AAAA record is requested (TCPv6 DNS name lookup), which resulted in no ip address. In other words: orafun.info only has an IPv4 ip address. So the two lookups actually do have a function.
2. TCP Socket (KGAS) p1=5, earlier annotated as ‘send’
These are the systemcalls that are visible and quite probably related to the send wait event:
--
-- file descriptor 12 holding the connection to the destination server is added to the epoll at file descriptor 9
--
epoll_ctl(9, EPOLL_CTL_ADD, 12, {EPOLLIN, {u32=3110998864, u64=139864426025808}}) = 0
--
-- Then the http get request is sent to the destination server at its normal file descriptor, 12.
--
write(12, "GET / HTTP/1.1\r\nHost: orafun.inf"..., 56) = 56
| 00000 47 45 54 20 2f 20 48 54 54 50 2f 31 2e 31 0d 0a GET / HTTP/1.1.. |
| 00010 48 6f 73 74 3a 20 6f 72 61 66 75 6e 2e 69 6e 66 Host: orafun.inf |
| 00020 6f 0d 0a 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 63 o..Connection: c |
| 00030 6c 6f 73 65 0d 0a 0d 0a lose.... |
--
-- And this is the wait event written by the process: TCP Socket (KGAS), p1=5
--
write(7, "WAIT #139864521752120: nam='TCP "..., 92) = 92
| 00000 57 41 49 54 20 23 31 33 39 38 36 34 35 32 31 37 WAIT #1398645217 |
| 00010 35 32 31 32 30 3a 20 6e 61 6d 3d 27 54 43 50 20 52120: nam='TCP |
| 00020 53 6f 63 6b 65 74 20 28 4b 47 41 53 29 27 20 65 Socket (KGAS)' e |
| 00030 6c 61 3d 20 33 39 35 20 20 3d 35 20 20 3d 30 20 la= 395 =5 =0 |
| 00040 20 3d 30 20 6f 62 6a 23 3d 36 36 32 20 74 69 6d =0 obj#=662 tim |
| 00050 3d 38 36 33 39 35 31 31 30 31 39 31 =86395110191 |
3. TCP Socket (KGAS) p1=6, earlier annotated as ‘receive’
--
-- Calling epoll_wait with timeout set to 0, so it doesn't block.
--
epoll_wait(9, [], 82, 0) = 0
--
-- And this is the wait event written by the process: TCP Socket (KGAS), p1=6
--
write(7, "WAIT #139864521752120: nam='TCP "..., 92) = 92
| 00000 57 41 49 54 20 23 31 33 39 38 36 34 35 32 31 37 WAIT #1398645217 |
| 00010 35 32 31 32 30 3a 20 6e 61 6d 3d 27 54 43 50 20 52120: nam='TCP |
| 00020 53 6f 63 6b 65 74 20 28 4b 47 41 53 29 27 20 65 Socket (KGAS)' e |
| 00030 6c 61 3d 20 31 35 30 20 20 3d 36 20 20 3d 30 20 la= 150 =6 =0 |
| 00040 20 3d 30 20 6f 62 6a 23 3d 36 36 32 20 74 69 6d =0 obj#=662 tim |
| 00050 3d 38 36 33 39 35 31 31 31 31 31 35 =86395111115 |
I have been thinking a lot about this seemingly weird call. It calls epoll_wait, but indicates it doesn’t want to wait (timeout=0), and even if epol_wait would have returned anything, indicated by a return code > 0, the epoll_event pointer is not set (indicated by []). The epoll file descriptor is used, but the only working file descriptor in the epoll is file descriptor 12, which has just been sent a http GET command, so the functionality of epoll is used.
This doesn’t make sense, unless you think about the asynchronous IO implementation of Oracle (see a lot of my earlier investigations), for which (in the case of asynchronous IO) io_getevents was called in a similar matter, timeout set to 0, to be able to do more requests while earlier IO requests are executed by the kernel. So my current theory here is that if multiple requests are happening, this mechanism provides a way to handle them.
If you have a simple single request, like in my case, this systemcall seems redundant. And because it queries the epoll file descriptor right after the request, it returns zero events, because there hardly has been any time after sending the http GET request.
4. Second TCP Socket (KGAS) p1=6, earlier annotated as ‘receive’
--
-- Calling epoll_wait with timeout set to 30000 (milliseconds).
--
epoll_wait(9, [{EPOLLIN, {u32=3110998864, u64=139864426025808}}], 82, 30000) = 1
--
-- And this is the second wait event written by the process: TCP Socket (KGAS), p1=6
--
write(7, "WAIT #139864521752120: nam='TCP "..., 95) = 95
| 00000 57 41 49 54 20 23 31 33 39 38 36 34 35 32 31 37 WAIT #1398645217 |
| 00010 35 32 31 32 30 3a 20 6e 61 6d 3d 27 54 43 50 20 52120: nam='TCP |
| 00020 53 6f 63 6b 65 74 20 28 4b 47 41 53 29 27 20 65 Socket (KGAS)' e |
| 00030 6c 61 3d 20 31 33 31 39 39 38 20 20 3d 36 20 20 la= 131998 =6 |
| 00040 3d 30 20 20 3d 30 20 6f 62 6a 23 3d 36 36 32 20 =0 =0 obj#=662 |
| 00050 74 69 6d 3d 38 36 33 39 35 32 34 33 37 36 34 tim=86395243764 |
This is the second time epoll_wait is called, and this one is blocking, because timeout has been set to 30000 milliseconds. If you look at the ela time, this took some time, and this now makes perfect sense: this system calls waits for an event to become available in the epoll, so it waits for the response of the remote http server. Please mind this call just notifies the userland process that the response is ready, the received data yet has to be read.
5. TCP Socket (KGAS) p1=4, earlier annotated as ‘receive’
--
-- At this point we know there is a response. First the original file descriptor is removed from the epoll:
--
epoll_ctl(9, EPOLL_CTL_DEL, 12, 0x7ffdea6b9710) = 0
--
-- The the response is read from file descriptor 12:
--
read(12, "HTTP/1.1 200 OK\r\nServer: nginx/1"..., 4096) = 2687
--
-- Then file descriptor 12 is added to the epoll again.
--
epoll_ctl(9, EPOLL_CTL_ADD, 12, {EPOLLIN, {u32=3110998864, u64=139864426025808}}) = 0
--
-- And a wait event written by the process: TCP Socket (KGAS), p1=4
--
write(7, "WAIT #139864521752120: nam='TCP "..., 92) = 92
| 00000 57 41 49 54 20 23 31 33 39 38 36 34 35 32 31 37 WAIT #1398645217 |
| 00010 35 32 31 32 30 3a 20 6e 61 6d 3d 27 54 43 50 20 52120: nam='TCP |
| 00020 53 6f 63 6b 65 74 20 28 4b 47 41 53 29 27 20 65 Socket (KGAS)' e |
| 00030 6c 61 3d 20 32 36 39 20 20 3d 34 20 20 3d 30 20 la= 269 =4 =0 |
| 00040 20 3d 30 20 6f 62 6a 23 3d 36 36 32 20 74 69 6d =0 obj#=662 tim |
| 00050 3d 38 36 33 39 35 32 34 35 31 38 32 =86395245182 |
So, what p1 set to 4 actually means, is that once the connection did return data, which is checked using epoll, and visible with p1 set to 6, it is read into the process. This is also the reason this takes very little time, this is the time to read data from kernelspace to user space, and to manage the connection’s file descriptor. It is taken off the epoll in order not to disturb it, and it is added again because there could be another request.
6. TCP Socket (KGAS) p1=3, earlier annotated as ‘close’
--
-- file descriptor 12 removed from the epoll
--
epoll_ctl(9, EPOLL_CTL_DEL, 12, 0x7ffdea6bac20) = 0
--
-- file descriptor 12 is closed, closing the network connection
--
close(12) = 0
--
-- And a wait event written by the process: TCP Socket (KGAS), p1=3
--
write(7, "WAIT #139864521752120: nam='TCP "..., 92) = 92
| 00000 57 41 49 54 20 23 31 33 39 38 36 34 35 32 31 37 WAIT #1398645217 |
| 00010 35 32 31 32 30 3a 20 6e 61 6d 3d 27 54 43 50 20 52120: nam='TCP |
| 00020 53 6f 63 6b 65 74 20 28 4b 47 41 53 29 27 20 65 Socket (KGAS)' e |
| 00030 6c 61 3d 20 33 35 32 20 20 3d 33 20 20 3d 32 20 la= 352 =3 =2 |
| 00040 20 3d 30 20 6f 62 6a 23 3d 36 36 32 20 74 69 6d =0 obj#=662 tim |
| 00050 3d 38 36 33 39 35 32 35 31 32 39 34 =86395251294 |
I don’t think this part holds any surprises. The network file descriptor is first removed from the epoll, and then it is closed, ending the TCP connection that was setup to perform a http request (in my case, I didn’t test, but I believe you will see the same with for example a SMTP connection, or any other type of TCP connection).
Summary
The basic message of this article is not surprising, nor does it conflict with current knowledge. Whenever you see a wait event ‘TCP Socket (KGAS)’, it means a foreground process is performing TCP networking via PLSQL. This wait event is a single event for creating, sending, receiving and closing a connection.
The true information of this article is how you can use the p1 value of the event to learn what actually the foreground is doing, and thus should give you more information to troubleshoot in the case of long waiting times.
TCP Socket (KGAS) p1 values:
1 - ?
2 - perform DNS lookup and create connection
3 - close connection
4 - copy TCP response into process space
5 - send request
6 - wait for TCP response to become available
7 - ?
8 - ? \
9 - ? | According to documentation, windows only in a 'special thread'.
10- ? /
Frits Hoogland Weblog 