strace & lsof during an application JDBC issue - simple questions at the end
- From: <Christopher.Taylor2@xxxxxxxxxxxx>
- To: <oracle-l@xxxxxxxxxxxxx>
- Date: Fri, 22 Mar 2013 02:30:41 -0500
I'm not terribly familiar with strace & lsof, but getting better by the day it
seems but I have a question and the manual isn't much help breaking this down
for me.
We have 2 servers involved:
serverA - application server talking to serverB database server
serverA is using a JDBC connection and started throwing heap errors and those
sessions exited the database.
serverA maintained other connections, however those connections went into a
bizarre state where they weren't really doing any "work" on the database, or
were doing it very slowly.
So, I did an strace and lsof of the PID for the connected session from the
database side.
Here's a sample of what I saw (stracing the connected session on the db server
side)
a.) for each READ(19, it would WAIT for a many seconds before it would output
anything again.
b.) the lsof info for file 19 indicates a network connection back to serverA
(the app server)
strace output:
read(19, 0x18fb8126, 2064) = ? ERESTARTSYS (To be restarted)
-------- WAITED HERE (see below)
--- SIGALRM (Alarm clock) @ 0 (0) ---
rt_sigprocmask(SIG_BLOCK, [], NULL, 8) = 0
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(52839),
sin_addr=inet_addr("10.26.68.146")},
msg_iov(2)=[{"\375\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0_W\202\f\2166-w\347\35\326f\252\306m\36\362\223\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(39067),
sin_addr=inet_addr("10.26.68.145")},
msg_iov(2)=[{"\375\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48}, {"\5\0\0\0\26\37W
\300\240\16T\347\35\326f\253\306m\36)\233\0\0\0\0\0\0\0\0\0\0"..., 136}],
msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(5298),
sin_addr=inet_addr("10.26.68.145")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0\272H\327qI\354\2770\347\35\326f\254\306m\36-\254\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(31333),
sin_addr=inet_addr("10.26.68.146")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0001lBuL\304\205e\347\35\326f\255\306m\36\31\220\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(43582),
sin_addr=inet_addr("10.26.68.146")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0\366L\"X\302\320\376\177\347\35\326f\256\306m\36\311\200\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(16526),
sin_addr=inet_addr("10.26.68.145")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0\255\24\367k\215\340\341\\\347\35\326f\257\306m\36\223\200\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(14883),
sin_addr=inet_addr("10.26.68.145")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0\214]\227Z\356\252\30\37\347\35\326f\246\306m\36\245\233\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(42073),
sin_addr=inet_addr("10.26.68.145")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48}, {"\5\0\0\0^rWC}Xq\r\347\35\326f\247\306m\36Y\242\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(33333),
sin_addr=inet_addr("10.26.68.146")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48}, {"\5\0\0\0\t\233\362
0\341\314}\347\35\326f\250\306m\36O\221\0\0\0\0\0\0\0\0\0\0"..., 136}],
msg_controllen=0, msg_flags=0}, 0) = 184
sendmsg(7, {msg_name(16)={sa_family¯_INET, sin_port=htons(39797),
sin_addr=inet_addr("10.26.68.146")},
msg_iov(2)=[{"\376\306-\0MRON\1\0\0\0\210\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,
48},
{"\5\0\0\0\333\367\5\n`\f\35O\347\35\326f\251\306m\36\210\220\0\0\0\0\0\0\0\0\0\0"...,
136}], msg_controllen=0, msg_flags=0}, 0) = 184
rt_sigprocmask(SIG_BLOCK, [ALRM], NULL, 8) = 0
setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={300, 0}}, NULL) = 0
rt_sigprocmask(SIG_UNBLOCK, [ALRM], NULL, 8) = 0
setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={300, 0}}, NULL) = 0
rt_sigprocmask(SIG_UNBLOCK, [], NULL, 8) = 0
rt_sigreturn(0x1) = 0
read(19, "\3`\0\0\6\0\0\0\0\0\3G\0\2\200P\1\30\0\0\0\0\1\1\7\1\1\2\0\1\1?"...,
2064) = 864 -------- WAITED HERE for some time before writing any additional
output
LSOF output:
oracle 8222 oracle 19u IPv4 13256047 0t0 TCP
SERVER_B_vip:hecmtl-db->SERVER_A_appserver.host.name:33747 (ESTABLISHED)
QUESTIONS:
Is the 864 at the end of the read line the number of SECONDS it took to
complete that operation?
Is a READ across a network link back to serverA a READ for more data - like a
SQLNET SQL*Net message from client event in the database?
Chris Taylor
Oracle DBA
Parallon IT&S
--
//www.freelists.org/webpage/oracle-l
Other related posts:
