Re: MMON_SLAVE seems high CPU with "select longname from javasnm$ where short = :1"
Date: Tue, 1 Dec 2015 19:44:58 +0300
Message-ID: <CACGsLCJNZp6ow27GNAgT6hOuuZd3L-M5wWyUAgbaW4yfnZsCMg_at_mail.gmail.com>
Just a shoot in the dark - what happens if you set java_jit_enabled=false on the system level
Theoretically it should disable JIT compiler for Java and I think all the work done by MMON should go away. It may impact performance of Java based code in any way though.
On Tuesday, 1 December 2015, Kim Berg Hansen <kibeha_at_gmail.com> wrote:
> Thanks, Stefan, very helpful :-)
>
>
> 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 <javascript:_e(%7B%7D,'cvml','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
> <javascript:_e(%7B%7D,'cvml','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
>> <javascript:_e(%7B%7D,'cvml','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 <javascript:_e(%7B%7D,'cvml','kibeha_at_kibeha.dk');>
>> <mailto:kibeha_at_kibeha.dk
>> <javascript:_e(%7B%7D,'cvml','kibeha_at_kibeha.dk');>>
>> > _at_kibeha <http://twitter.com/kibeha>
>>
>
>
-- Regards Timur Akhmadeev -- http://www.freelists.org/webpage/oracle-lReceived on Tue Dec 01 2015 - 17:44:58 CET