shared pool latching issue and missing time in trace file
From: Sigrid Keydana <keydana_at_gmx.de>
Date: Tue, 11 Jun 2013 10:12:19 +0200 (CEST)
Message-ID: <trinity-504e1280-8d8c-4b6d-b49d-8cc05a297d73-1370938339129_at_3capp-gmx-bs47>
Hi, I'd like to ask for your advice debugging a shared pool latching problem. For background, let me state that in general, in the application concerned, shared pool fragmentation has been a known issue, but less so in the present since quite some work has been done to reduce hard parsing. However, there is a statement (which I cannot reproduce here but might do so in a masked form if required) that regularly causes the alert (deemed "harmless" by Oracle Support, see 330239.1): Memory Notification: Library Cache Object loaded into SGA Heap size 75750K exceeds notification threshold (51200K) I have been tracing this statement in 3 different conditions: - asSYS user on the database server - as non-SYS user from sqlplus, on the database server - as non-SYS user from a client machine, using PL/SQLDeveloper 1) SYS on db server In this case, I see a small number of recursive statements in the tracefile, and parse cpu/elapsed time is c=419936,e=420700. No "memory notification" in the alert log. Query executes smoothly. 2) non-SYS on db server, using sqlplus Here, the query does not execute smoothly. Before the entries for the recursive sqls, I have the following lines: .. *** ACTION NAME:() 2013-06-10 15:31:32.544 WAIT
#47026981749560: nam='latch: shared pool' ela= 65 address=1611705384
number=307 tries=0 obj#=0 tim=1370871092544435 *** 2013-06-10 15:31:46.136 WAIT #47026981749560: nam='latch: row cache objects' ela= 119 address=32940374584 number=280 tries=0 obj#=0 tim=1370871106136480 *** 2013-06-10 15:33:50.873 WAIT #47026981749560: nam='latch: shared pool'ela= 9308 address=1611705384 number=307 tries=0 obj#=0 tim=1370871230873117 WAIT #47026981749560: nam='latch: shared pool' ela= 204 address=1611705384 number=307 tries=0 obj#=0 tim=1370871230873406 Parse time is c=261363267,e=261410049 - so parsing took more than 4 minutes. What I don't understand is what happened during all this time - the 4 wait events reported look far "too short" to match the actual time elapsed (e.g., the longest shared pool latch wait accounting for 9 ms only…) (And just in parentheses, the recursive queries turn out to be very quick). In spite of the long query duration, no memory notification occurred. 3) non-SYS from PL/SQLDeveloper Lastly, apart from the fact that the PL/SQLDeveloper trace file is messed up by lots of (for me :-)) unexpected sql (at dep=0!), it resembles the second case for the "how was the time spent"part: ** 2013-06-06 12:04:21.832 WAIT #47816534037856: nam='latch: shared pool' ela= 1012 address=1611705224 number=307 tries=0 obj#=-1 tim=1370513061832831 WAIT #47816534037856: nam='latch: row cache objects' ela= 94 address=33352528640 number=280 tries=0 obj#=-1tim=1370513061833689 *** 2013-06-06 12:04:21.881 WAIT
#47816534037856: nam='latch: row cache objects' ela= 170
address=33352528640 number=280 tries=0 obj#=-1 tim=1370513061881325 *** 2013-06-06 12:04:57.512 WAIT #47816534037856: nam='latch: row cache objects' ela= 641 address=32940374584 number=280 tries=0 obj#=-1 tim=1370513097512746 *** 2013-06-06 12:05:05.639 WAIT #47816534037856: nam='latch: shared pool' ela= 3 address=1611705224 number=307 tries=0obj#=-1 tim=1370513105639833 *** 2013-06-06 12:07:59.226 WAIT
#47816534037856: nam='latch: row cache objects' ela= 76
address=32824711104 number=280 tries=0 obj#=-1 tim=1370513279226650 *** 2013-06-06 12:08:13.053 WAIT #47816534037856: nam='latch: shared pool'ela= 369 address=1611705224 number=307 tries=0 obj#=-1 tim=1370513293053337 *** 2013-06-06 12:08:22.800 WAIT #47816533789368: nam='library cache lock' ela= 265 handle address=33747902984 lock address=33507635152 100*mode+namespace=1632087638018 obj#=-1 tim=1370513302800299 WAIT #47816533789368: nam='library cache pin' ela= 180 handle address=33747902984 pin address=33507634896 100*mode+namespace=1632087638018 obj#=-1 tim=1370513302800606 WAIT
#47816533853720: nam='library cache lock' ela= 458 handle
address=33475669128 lock address=33527516264 100*mode+namespace=124554379266 obj#=-1 tim=1370513302802113 In this scenario, however, contrary to the sqlplus execution, I can bet I will get the memory notification in the alert log. Please excuse the long description - now these are my questions: 1) In cases 2 and 3, where is the time spent? 2) What might be the relation between the the long waits and the "memory notification" alert, given there seems to be no 1:1 relationship? What do you think, how should on judge/reacton this alert? 3) In general, would you have any advice how to proceed with this issue? Is it even worthwhile to follow up questions like "why this is parsed quickly when issued by SYS, but not otherwise", or to tryto do more of "shared pool diagnostics / debugging" (given that in general, some level of fragmentation will be unavoidable due to how the application works)? So perhaps, concentrate on tuning this specific sql, rather? I'd be very glad about any advice / opinions on this. Thanks inadvance, Sigrid
Date: Tue, 11 Jun 2013 10:12:19 +0200 (CEST)
Message-ID: <trinity-504e1280-8d8c-4b6d-b49d-8cc05a297d73-1370938339129_at_3capp-gmx-bs47>
Hi, I'd like to ask for your advice debugging a shared pool latching problem. For background, let me state that in general, in the application concerned, shared pool fragmentation has been a known issue, but less so in the present since quite some work has been done to reduce hard parsing. However, there is a statement (which I cannot reproduce here but might do so in a masked form if required) that regularly causes the alert (deemed "harmless" by Oracle Support, see 330239.1): Memory Notification: Library Cache Object loaded into SGA Heap size 75750K exceeds notification threshold (51200K) I have been tracing this statement in 3 different conditions: - asSYS user on the database server - as non-SYS user from sqlplus, on the database server - as non-SYS user from a client machine, using PL/SQLDeveloper 1) SYS on db server In this case, I see a small number of recursive statements in the tracefile, and parse cpu/elapsed time is c=419936,e=420700. No "memory notification" in the alert log. Query executes smoothly. 2) non-SYS on db server, using sqlplus Here, the query does not execute smoothly. Before the entries for the recursive sqls, I have the following lines: .. *** ACTION NAME:() 2013-06-10 15:31:32.544 WAIT
#47026981749560: nam='latch: shared pool' ela= 65 address=1611705384
number=307 tries=0 obj#=0 tim=1370871092544435 *** 2013-06-10 15:31:46.136 WAIT #47026981749560: nam='latch: row cache objects' ela= 119 address=32940374584 number=280 tries=0 obj#=0 tim=1370871106136480 *** 2013-06-10 15:33:50.873 WAIT #47026981749560: nam='latch: shared pool'ela= 9308 address=1611705384 number=307 tries=0 obj#=0 tim=1370871230873117 WAIT #47026981749560: nam='latch: shared pool' ela= 204 address=1611705384 number=307 tries=0 obj#=0 tim=1370871230873406 Parse time is c=261363267,e=261410049 - so parsing took more than 4 minutes. What I don't understand is what happened during all this time - the 4 wait events reported look far "too short" to match the actual time elapsed (e.g., the longest shared pool latch wait accounting for 9 ms only…) (And just in parentheses, the recursive queries turn out to be very quick). In spite of the long query duration, no memory notification occurred. 3) non-SYS from PL/SQLDeveloper Lastly, apart from the fact that the PL/SQLDeveloper trace file is messed up by lots of (for me :-)) unexpected sql (at dep=0!), it resembles the second case for the "how was the time spent"part: ** 2013-06-06 12:04:21.832 WAIT #47816534037856: nam='latch: shared pool' ela= 1012 address=1611705224 number=307 tries=0 obj#=-1 tim=1370513061832831 WAIT #47816534037856: nam='latch: row cache objects' ela= 94 address=33352528640 number=280 tries=0 obj#=-1tim=1370513061833689 *** 2013-06-06 12:04:21.881 WAIT
#47816534037856: nam='latch: row cache objects' ela= 170
address=33352528640 number=280 tries=0 obj#=-1 tim=1370513061881325 *** 2013-06-06 12:04:57.512 WAIT #47816534037856: nam='latch: row cache objects' ela= 641 address=32940374584 number=280 tries=0 obj#=-1 tim=1370513097512746 *** 2013-06-06 12:05:05.639 WAIT #47816534037856: nam='latch: shared pool' ela= 3 address=1611705224 number=307 tries=0obj#=-1 tim=1370513105639833 *** 2013-06-06 12:07:59.226 WAIT
#47816534037856: nam='latch: row cache objects' ela= 76
address=32824711104 number=280 tries=0 obj#=-1 tim=1370513279226650 *** 2013-06-06 12:08:13.053 WAIT #47816534037856: nam='latch: shared pool'ela= 369 address=1611705224 number=307 tries=0 obj#=-1 tim=1370513293053337 *** 2013-06-06 12:08:22.800 WAIT #47816533789368: nam='library cache lock' ela= 265 handle address=33747902984 lock address=33507635152 100*mode+namespace=1632087638018 obj#=-1 tim=1370513302800299 WAIT #47816533789368: nam='library cache pin' ela= 180 handle address=33747902984 pin address=33507634896 100*mode+namespace=1632087638018 obj#=-1 tim=1370513302800606 WAIT
#47816533853720: nam='library cache lock' ela= 458 handle
address=33475669128 lock address=33527516264 100*mode+namespace=124554379266 obj#=-1 tim=1370513302802113 In this scenario, however, contrary to the sqlplus execution, I can bet I will get the memory notification in the alert log. Please excuse the long description - now these are my questions: 1) In cases 2 and 3, where is the time spent? 2) What might be the relation between the the long waits and the "memory notification" alert, given there seems to be no 1:1 relationship? What do you think, how should on judge/reacton this alert? 3) In general, would you have any advice how to proceed with this issue? Is it even worthwhile to follow up questions like "why this is parsed quickly when issued by SYS, but not otherwise", or to tryto do more of "shared pool diagnostics / debugging" (given that in general, some level of fragmentation will be unavoidable due to how the application works)? So perhaps, concentrate on tuning this specific sql, rather? I'd be very glad about any advice / opinions on this. Thanks inadvance, Sigrid
-- http://www.freelists.org/webpage/oracle-lReceived on Tue Jun 11 2013 - 10:12:19 CEST