strace & lsof during an application JDBC issue - simple questions at the end

From: <Christopher.Taylor2_at_parallon.net>
Date: Fri, 22 Mar 2013 02:30:41 -0500
Message-ID: <F05D8DF1FB25F44085DB74CB916678E8879B53CA11_at_NADCWPMSGCMS10.hca.corpad.net>

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) _at_ 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

--

http://www.freelists.org/webpage/oracle-l Received on Fri Mar 22 2013 - 08:30:41 CET