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@xxxxxxxxx
@kibeha <http://twitter.com/kibeha>
On Tue, Dec 1, 2015 at 10:53 AM, Stefan Koehler <contact@xxxxxxxx> 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 bindvariable content to find out which Java identifiers are being looked up. But
no trace file is created in the usual place? (The session also hasAudSid=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 CloudControl 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 withthat 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: @OracleSK
Kim Berg Hansen <kibeha@xxxxxxxxx> hat am 1. Dezember 2015 um 09:53geschrieben:
11.2.0.3.0 - 64bit Production on Oracle Linux Server release 6.5 with 4
Hi, List
We have a database Oracle Database 11g Enterprise Edition Release
cores.
look at top activity in Cloud Control (or Enterprise Manager or whatever it
One statement seems to practically continously use 20% of a core when I
is called):Action=JAVAVM JIT slave action.
select longname
from javasnm$
where short = :1
All of it executed by a single session with Module=MMON_SLAVE,
be huge amounts.
We do use some Java and XML in the database, but I do not believe it to
Besides, I would think then it would be executed in user processes andnot this single background process?
variable content to find out which Java identifiers are being looked up.
I have tried to enable trace for the session in order to examine bind
But no trace file is created in the usual place? (The session also hasAudSid=0 and AudSid usually is part of trace file name as far as I know.)
directory? If so, where can I find which directory?
Q1: Are trace files from background processes placed in other
11.1 that should be fixed in 11.2.
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
Control is not actually CPU expenditure but wrongly reported?
Q2: Is it possible the 20% of a core CPU expenditure shown in Cloud
that statement?
Q3: Any suggestions for how to dig into what actually is happening with
(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@xxxxxxxxx <mailto:kibeha@xxxxxxxxx>
@kibeha <http://twitter.com/kibeha>
