JDBC application causes intermittent high load and latch waits

From: <JayMiller_at_TDWaterhouse.com>
Date: Wed, 23 Jul 2003 17:12:19 -0400
Message-Id: <25998.339271@fatcity.com>

This message is in MIME format. Since your mail reader does not understand this format, some or all of this message may not be legible.

------_=_NextPart_001_01C3515E.E27EDC0F
Content-Type: text/plain

Oracle 8.1.5.1
Solaris 2.6

Hi there,

For the last few days one of our servers will suddenly experience ridiculously high load averages (50-65) and all applications grind to a halt.

Restarting the database solves the problem and shutting down a specific apps servers solves the problem. This apps server generally has about 2-3 JDBC connections to the database. I just started looking at it today (it's not one of my databases) and when it recurred I started checking wait events.

The top 10 wait events for about a 2 minute period were as follows:

EVENT                                    Delta Waits      Delta Timeouts 
latch free                                  317376          185591

SQL*Net message from client              66435           0             
SQL*Net message to client                  66419           0             
db file sequential read               21709           0             
SQL*Net more data to client                18066           0             
file open                                   1223                0          
rdbms ipc message                   576     170     
log file sync                               519     1          
log file parallel write                  374     0          
log file sequential read               343     0

It looks like a latch contention problem. By the time I drilled down to specific sessions that were experiencing the "latch free" wait the apps server had been restarted. My query showed most waiting on the "process allocation" latch but I don't know for sure that this was the latch that was causing the problem during the high load period.

I prepared this query to run the next time the problem occurs in order to identify which latches are being waited on:

select s.sid,s.username,s.program,s.status, se.event,se.total_waits,se.total_timeouts, se.time_waited,se.average_wait,sw.p2,v.name from v$session s, v$session_event se, v$session_wait sw,v$latch v where s.sid=se.sid
and s.sid=sw.sid
and sw.p2=l.latch#
and s.status='ACTIVE'
AND S.USERNAME IS NOT NULL
and se.event='latch free';

Does this make sense? Any suggestions for other things to check? Some reading suggests that latch contention is often caused by not using bind variables and that increasing db_block_lru_latches (currently = 2) can alleviate the problem while the code is being fixed.

But the question is why this problem suddenly happens and the problem doesn't go away until the apps server is shut down. The old version of the application (which didn't use JDBC) did not have this problem. I'm theorizing that perhaps JDBC handles its connections differently and after waiting for some period of time resends the transaction and keeps resending it faster than Oracle can clean things up?

Has anyone experienced a similar problem or have other suggestions of where to go from here?

Thanks,
Jay Miller

------_=_NextPart_001_01C3515E.E27EDC0F
Content-Type: text/html
Content-Transfer-Encoding: quoted-printable

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 Transitional//EN">
<html xmlns:v=3D"urn:schemas-microsoft-com:vml" =
xmlns:o=3D"urn:schemas-microsoft-com:office:office" = xmlns:w=3D"urn:schemas-microsoft-com:office:word" = xmlns=3D"http://www.w3.org/TR/REC-html40">

<head>
<META HTTP-EQUIV=3D"Content-Type" CONTENT=3D"text/html; =
charset=3Dus-ascii">

<meta name=3DProgId content=3DWord.Document>
<meta name=3DGenerator content=3D"Microsoft Word 10">
<meta name=3DOriginator content=3D"Microsoft Word 10">
<link rel=3DFile-List href=3D"cid:filelist.xml_at_01C3513D.92466E10">
<!--[if gte mso 9]><xml>
<w:WordDocument>

  <w:SpellingState>Clean</w:SpellingState>
  <w:GrammarState>Clean</w:GrammarState>
  <w:DocumentKind>DocumentEmail</w:DocumentKind>
  <w:EnvelopeVis/>
  <w:Compatibility>
   <w:ForgetLastTabAlignment/>

<w:DoNotUseHTMLParagraphAutoSpacing/> </w:Compatibility>

  <w:BrowserLevel>MicrosoftInternetExplorer4</w:BrowserLevel>
 </w:WordDocument>

</xml><![endif]-->
<style>
<!--

/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal

	{mso-style-parent:"";
	margin:0in;
	margin-bottom:.0001pt;
	mso-pagination:widow-orphan;
	font-size:12.0pt;
	font-family:"Times New Roman";
	mso-fareast-font-family:"Times New Roman";}
a:link, span.MsoHyperlink
	{color:blue;
	text-decoration:underline;
	text-underline:single;}
a:visited, span.MsoHyperlinkFollowed
	{color:purple;
	text-decoration:underline;
	text-underline:single;}
p.MsoAutoSig, li.MsoAutoSig, div.MsoAutoSig
	{margin:0in;
	margin-bottom:.0001pt;
	mso-pagination:widow-orphan;
	font-size:12.0pt;
	font-family:"Times New Roman";
	mso-fareast-font-family:"Times New Roman";}
span.EmailStyle17
	{mso-style-type:personal-reply;
	mso-style-noshow:yes;
	mso-ansi-font-size:10.0pt;
	mso-bidi-font-size:10.0pt;
	font-family:Arial;
	mso-ascii-font-family:Arial;
	mso-hansi-font-family:Arial;
	mso-bidi-font-family:Arial;
	color:navy;}
span.SpellE
	{mso-style-name:"";
	mso-spl-e:yes;}
span.GramE
	{mso-style-name:"";
	mso-gram-e:yes;}
@page Section1
	{size:8.5in 11.0in;
	margin:1.0in 66.25pt 1.0in 66.25pt;
	mso-header-margin:.5in;
	mso-footer-margin:.5in;
	mso-paper-source:0;}
div.Section1
	{page:Section1;}

-->
</style>
<!--[if gte mso 10]>
<style>

/* Style Definitions */=20
table.MsoNormalTable

	{mso-style-name:"Table Normal";
	mso-tstyle-rowband-size:0;
	mso-tstyle-colband-size:0;
	mso-style-noshow:yes;
	mso-style-parent:"";
	mso-padding-alt:0in 5.4pt 0in 5.4pt;
	mso-para-margin:0in;
	mso-para-margin-bottom:.0001pt;
	mso-pagination:widow-orphan;
	font-size:10.0pt;
	font-family:"Times New Roman";}

</style>
<![endif]-->
</head>

<body bgcolor=3Dwhite lang=3DEN-US link=3Dblue vlink=3Dpurple =
style=3D'tab-interval:.5in'>

<div class=3DSection1>

<div>

Oracle = 8.1.5.1<o:p></o:p>

Solaris = 2.6<o:p></o:p>

<o:p> </o:p></p= >

Hi = there,<o:p></o:p>

<o:p> </o:p></p= >

For the last few days one of our = servers
will suddenly experience ridiculously high load averages (50-65) and = all
applications grind to a halt.<o:p></o:p>

<o:p> </o:p></p= >

Restarting the database solves = the problem
and shutting down a specific apps servers = solves the
problem.  This apps server = generally has
about 2-3 JDBC connections to the database. 
I just started looking at it today (it's not one of my =
databases) and when
it recurred I started checking wait =
events.<o:p></o:p>

<o:p> </o:p></p= >

The top 10 wait events for about = a 2 minute
period were as follows:<o:p></o:p>

<o:p> </o:p></p= >

EVENT<span =

style=3D'mso-tab-count:3'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbs=
p;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbs=
p;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbs=

p;    Delta
Waits      =
Delta Timeouts<span

style=3D'mso-tab-count:1'> <o:p></o:p>

<o:p></o:p>

<span =

style=3D'font-size:12.0pt;color:navy'>latch</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> free<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=
sp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;              =
317376       &nb= sp; 
185591       &nb= sp;      =
<o:p></o:p>

SQL*Net message from client       =
       =
66435<span

style=3D'mso-spacerun:yes'>       &nb= sp;   0       =
      =
<o:p></o:p>

SQL*Net message to client       &nb= sp;        &nbs= p; 66419       &nb= sp;   0       =
      =
<o:p></o:p>

<span =

style=3D'font-size:12.0pt;color:navy'>db</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> file sequential read<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;       21709       &nb= sp;   0       =
      =
<o:p></o:p>

SQL*Net more data to client       =
       &nbs= p; 18066       &nb= sp;   0       =
      =
<o:p></o:p>

<span =

style=3D'font-size:12.0pt;color:navy'>file</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> open<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;           &nb= sp;            &nbs= p;  1223   
       &nbs= p;    0       =
   =
<o:p></o:p>

rdbms<= font

color=3Dnavy><span style=3D'color:navy'> <span =
class=3DSpellE>ipc</span> message<span
style=3D'mso-spacerun:yes'>&nbsp; </span><span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;       <span =

style=3D'mso-tab-count:1'>&nbsp; </span>576<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp; </span><span =
style=3D'mso-tab-count:1'> </span>170<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp; </span><span =
style=3D'mso-tab-count:1'> </span><o:p></o:p></span></font></p>

<span =

style=3D'font-size:12.0pt;color:navy'>log</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> file sync<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;           &nb= sp;           =
519     =
<span

style=3D'mso-tab-count:1'> 1       =
<span

style=3D'mso-tab-count:1'>   =
<o:p></o:p>

<span =

style=3D'font-size:12.0pt;color:navy'>log</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> file parallel write<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;          =
374<span

style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp; </span><span =
style=3D'mso-tab-count:1'> </span>0<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; =

   =
<o:p></o:p>

<span =

style=3D'font-size:12.0pt;color:navy'>log</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> file sequential read<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nb=

sp;  <span =

style=3D'mso-tab-count:1'>&nbsp;&nbsp;&nbsp;&nbsp; </span>343<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp; </span><span =
style=3D'mso-tab-count:1'> </span>0<span
style=3D'mso-spacerun:yes'>&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; =

   =
<o:p></o:p>

<o:p> </o:p></p= >

It looks like a latch contention problem.  By the time I = drilled down to
specific sessions that were experiencing the "latch free" = wait the
apps server had been restarted.  =
My query

showed most waiting on the "process allocation" latch but I = don't
know for sure that this was the latch that was causing the problem = during the
high load period.<o:p></o:p>

<o:p> </o:p></p= >

I prepared this query to run the = next time
the problem occurs in order to identify which latches are being waited = on:<o:p></o:p>

<o:p> </o:p></p= >

<span =

style=3D'font-size:12.0pt;color:navy'>select</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> <span =
class=3DSpellE>s.sid,s.username,s.program,s.status</span>,<o:p></o:p></s=

pan>

se.event,se.total_waits,se.total_timeouts</sp= an>,<o:p></o:p>

se.time_waited,se.average_wait,sw.p2,v.name<o:p></o:p></fo= nt>

<span =

style=3D'font-size:12.0pt;color:navy'>from</span></font></span><font
color=3Dnavy><span style=3D'color:navy'> <span =
class=3DSpellE>v$session</span> s, <span
class=3DSpellE>v$session_event</span> se, <span =
class=3DSpellE>v$session_wait</span>

sw,v$latch v<o:p></o:p>

<span

style=3D'font-size:12.0pt;color:navy'><span =
style=3D'mso-spacerun:yes'>&nbsp;</span><span
class=3DGramE>where</span> <span class=3DSpellE>s.sid</span>=3D<span =
class=3DSpellE>se.sid</span><o:p></o:p></span></font></p>

<span

style=3D'font-size:12.0pt;color:navy'><span =
style=3D'mso-spacerun:yes'>&nbsp;</span><span
class=3DGramE>and</span> <span class=3DSpellE>s.sid</span>=3D<span =
class=3DSpellE>sw.sid</span><o:p></o:p></span></font></p>

<span

style=3D'font-size:12.0pt;color:navy'><span =
style=3D'mso-spacerun:yes'>&nbsp;</span><span
class=3DGramE>and</span> sw.p2=3D<span =
class=3DSpellE>l.latch</span>#<o:p></o:p></span></font></p>

<span

style=3D'font-size:12.0pt;color:navy'><span =
style=3D'mso-spacerun:yes'>&nbsp;</span><span
class=3DGramE>and</span> <span =
class=3DSpellE>s.status</span>=3D'ACTIVE'<o:p></o:p></span></font></p>

 AND S.USERNAME IS NOT NULL<o:p></o:p>

<span

style=3D'font-size:12.0pt;color:navy'><span =
style=3D'mso-spacerun:yes'>&nbsp;</span><span
class=3DGramE>and</span> <span class=3DSpellE>se.event</span>=3D'latch =

free';<o:p></o:p>

<o:p> </o:p></p= >

Does this make sense?  Any = suggestions for other things
to check?  Some = reading suggests
that latch contention is often caused by not using bind variables and = that
increasing db_block_lru_latches (currently = =3D 2) can
alleviate the problem while the code is being = fixed.<o:p></o:p>

<o:p> </o:p></p= >

But the question is why this = problem
suddenly happens and the problem doesn't go away until the apps server = is shut
down.  The old version of = the application
(which didn't use JDBC) did not have this problem.  I'm theorizing that perhaps = JDBC handles its
connections differently and after waiting for some period of time = resends the
transaction and keeps resending it faster than Oracle can clean things = up?   =
<o:p></o:p>

<o:p> </o:p></p= >

Has anyone experienced a similar = problem or
have other suggestions of where to go from = here?<o:p></o:p>

<o:p> </o:p></p= Received on Wed Jul 23 2003 - 16:12:19 CDT