Re: MMON_SLAVE seems high CPU with "select longname from javasnm$ where short = :1"

I got to be able to dig a bit deeper using oradebug (never had the need to use that tool before ;-)

First I checked the OS process. It seems to sleep about 15 seconds or so, then wake up and heavy burn CPU about 3 seconds or so (wall clock timing.) Seems to fit an average of approx 20% of a core when evening the numbers out.

Using session browser in Toad the M000 background session is always ACTIVE with current statement:

select longname
  from javasnm$
 where short = :1

Keeping refreshing "Waits" tab in the session browser I see:

• Wait event "JOX Jit Process Sleep" is in state "Waiting" 15 seconds or so.
• Then it is in state "Waited Known Time" for 3 seconds or so.
• Repeating over and over.

Using oradebug to attach to the pid, I managed to get the session to trace with:

oradebug setorapid 134
oradebug event 10046 trace name context forever, level 12

Trace file contains the wait event repeated approx every 18 seconds:

• 2015-12-01 14:11:25.857 WAIT #0: nam='JOX Jit Process Sleep' ela= 15004991 p1=0 p2=0 p3=0 obj#=561 tim=1448975485857757
• 2015-12-01 14:11:43.595 WAIT #0: nam='JOX Jit Process Sleep' ela= 15003838 p1=0 p2=0 p3=0 obj#=561 tim=1448975503595530
• 2015-12-01 14:12:01.432 WAIT #0: nam='JOX Jit Process Sleep' ela= 15007063 p1=0 p2=0 p3=0 obj#=561 tim=1448975521432543

No sign of actually executing the SQL statement??? That made me re-check and "Executions" for the SQL Id does *not* increase every 18 seconds....!

Again with oradebug I made a couple errorstack dumps like you suggested. Finding the cursor I found the content of the bind variable:

 bind#0
  oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00   oacflg=18 fl2=0001 frm=01 csi=31 siz=32 off=0   kxsbbbfp=7fc793995220 bln=32 avl=30 flg=05   value="/de53220_InternalTypeMappingRe"

The same bind content every errorstack dump I made. But if the statement isn't actually executed, then that might be a red herring?

There are just a couple places in my trace that is not just "JOX Jit Process Sleep":

• 2015-12-01 14:13:48.520 WAIT #0: nam='JOX Jit Process Sleep' ela= 15004870 p1=0 p2=0 p3=0 obj#=561 tim=1448975628520527
• 2015-12-01 14:13:49.407 WAIT #0: nam='library cache: mutex X' ela= 7 idn=48961 value=0 where=49 obj#=561 tim=1448975629407906
• 2015-12-01 14:14:06.214 WAIT #0: nam='JOX Jit Process Sleep' ela= 15003873 p1=0 p2=0 p3=0 obj#=561 tim=1448975646214563

......

• 2015-12-01 14:23:49.668 WAIT #0: nam='JOX Jit Process Sleep' ela= 15004150 p1=0 p2=0 p3=0 obj#=561 tim=1448976229668597
• 2015-12-01 14:24:07.243 WAIT #0: nam='JOX Jit Process Sleep' ela= 15003443 p1=0 p2=0 p3=0 obj#=561 tim=1448976247243544 WAIT #0: nam='JOX Jit Process Sleep' ela= 15004392 p1=0 p2=0 p3=0 obj#=561 tim=1448976265313552
• 2015-12-01 14:24:27.828 WAIT #0: nam='latch: shared pool' ela= 39 address=1611704904 number=307 tries=0 obj#=561 tim=1448976267828962
• 2015-12-01 14:24:42.869 WAIT #0: nam='JOX Jit Process Sleep' ela= 15004783 p1=0 p2=0 p3=0 obj#=561 tim=1448976282869634

So my M000 MMON_SLAVE background process appears to do an approximately 18 second cycle - 15 seconds idle, 3 seconds CPU burn. But only the single wait event 'JOX Jit Process Sleep' once every 18 seconds is to be seen in the trace file.

Is there a different event than 10046 which I could enable using oradebug that more specifically shows what is happening CPU-wise?

Regards

Kim Berg Hansen

http://www.kibeha.dk
kibeha_at_kibeha.dk
_at_kibeha <http://twitter.com/kibeha>

On Tue, Dec 1, 2015 at 10:53 AM, Stefan Koehler <contact_at_soocs.de> wrote:

> Hi Kim,
> i have no idea about all that JVM dev stuff, but can possibly answer some
> of your questions.
>
>
> > I have tried to enable trace for the session in order to examine bind
> variable content to find out which Java identifiers are being looked up. But
> > no trace file is created in the usual place? (The session also has
> AudSid=0 and AudSid usually is part of trace file name as far as I know.)
>
> If the SQL is still running and burning up CPU only, you won't see
> any(thing) in trace file until another db-/syscall is executed. However you
> can
> also dump the bind variables of an existing cursor / running SQL without
> SQL trace. Just dump an errorstack and search for "Session Cursor Dump":
> SQL> oradebug setospid <PID_OF_MMON_SLAVE>
> SQL> oradebug dump errorstack 3
>
>
> > Q1: Are trace files from background processes placed in other directory?
> If so, where can I find which directory?
> No. DIAG directory in folder trace.
>
>
> > Q2: Is it possible the 20% of a core CPU expenditure shown in Cloud
> Control is not actually CPU expenditure but wrongly reported?
> If you have 4 CPUs and one process is running on CPU only - 20% could be
> reasonable. However i would always use OS tools to verify this.
>
>
> > Q3: Any suggestions for how to dig into what actually is happening with
> that statement?
> Check execution plan, capture and check session statistics, capture stack
> traces. CPU issues could be more difficult to troubleshoot, but maybe my
> latest DOAG talk about this may help and point you in the right direction:
> http://www.soocs.de/public/talk/
>
> Best Regards
> Stefan Koehler
>
> Freelance Oracle performance consultant and researcher
> Homepage: http://www.soocs.de
> Twitter: _at_OracleSK
>
> > Kim Berg Hansen <kibeha_at_gmail.com> hat am 1. Dezember 2015 um 09:53
> geschrieben:
> >
> > Hi, List
> >
> > We have a database Oracle Database 11g Enterprise Edition Release
> 11.2.0.3.0 - 64bit Production on Oracle Linux Server release 6.5 with 4
> cores.
> >
> > One statement seems to practically continously use 20% of a core when I
> look at top activity in Cloud Control (or Enterprise Manager or whatever it
> > is called):
> >
> > select longname
> > from javasnm$
> > where short = :1
> >
> > All of it executed by a single session with Module=MMON_SLAVE,
> Action=JAVAVM JIT slave action.
> >
> > We do use some Java and XML in the database, but I do not believe it to
> be huge amounts.
> > Besides, I would think then it would be executed in user processes and
> not this single background process?
> >
> > I have tried to enable trace for the session in order to examine bind
> variable content to find out which Java identifiers are being looked up.
> > But no trace file is created in the usual place? (The session also has
> AudSid=0 and AudSid usually is part of trace file name as far as I know.)
> >
> > Q1: Are trace files from background processes placed in other
> directory? If so, where can I find which directory?
> >
> >
> > The wait event for the session seem to be JOX Jit Process Sleep.
> > As far as I can tell it is an idle event.
> > MOS note 1075283.1 describes it might show up in top list as a bug in
> 11.1 that should be fixed in 11.2.
> >
> > Q2: Is it possible the 20% of a core CPU expenditure shown in Cloud
> Control is not actually CPU expenditure but wrongly reported?
> >
> >
> > Q3: Any suggestions for how to dig into what actually is happening with
> that statement?
> > (Keeping in mind I am primarily a developer ;-)
> >
> >
> > Thanks in advance for any hints I might use for further digging.
> >
> >
> > Regards
> >
> >
> > Kim Berg Hansen
> >
> > http://www.kibeha.dk
> > kibeha_at_kibeha.dk <mailto:kibeha_at_kibeha.dk>
> > _at_kibeha <http://twitter.com/kibeha>
>

--
http://www.freelists.org/webpage/oracle-l