Oracle database internals by Riyaj

Discussions about Oracle performance tuning, RAC, Oracle internal & E-business suite.

library cache lock on BUILD$ object

Posted by Riyaj Shamsudeen on May 21, 2016

I was testing an application performance in 12c, and one job was constantly running slower than 11g. This post is to detail the steps. I hope the steps would be useful if you encounter similar issue.

Problem

In an one hour period, over 90% of the DB time spent on waiting for library cache lock waits. Upon investigation, one statement was suffering from excessive waits for ‘library cache lock’ event. We recreated the problem and investigated it further to understand the issue.

Following is the output of wait_details_rac.sql script (that I will upload here) and there are many PX query servers are waiting for ‘library cache lock’ wait event.

   SID PID        EVENT                          USERNAME   OSUSER     STATE               WAIT_TIME   WIS P1_P2_P3_TEXT
------ ---------- ------------------------------ ---------- ---------- ------------------- --------- ----- ----------------------------------------
                                                                                                            2163

   276  12445     library cache lock             TST_USR    test       WAITING                     0     1 handle address 399021346904-lock address
                                                                                                            2147

   288  12449     library cache lock             TST_USR    test       WAITING                     0     4 handle address 399021346904-lock address
                                                                                                            2136

   303  12453     library cache lock             TST_USR    test       WAITING                     0     4 handle address 399021346904-lock address
                                                                                                            2136

   315  12457     library cache lock             TST_USR    test       WAITING                     0     4 handle address 399021346904-lock address
 ...Snipped..                                                                                                           2152

Lock address to object

For all session waiting, library cache handle address is the same. That means that the sessions are waiting for one library cache object. Querying x$kgllk confirms that and we can also identify object name.

  select ses.sid, ses.serial#,lck.kgllkcnt, lck.kgllkmod,lck.kgllkreq, lck.kglnaobj
  from x$kgllk lck , v$session ses
  where kgllkhdl in
     (select kgllkhdl from x$kgllk where kgllkreq >0)
  and lck.KGLLKUSE = ses.saddr
/
   SID    SERIAL#   KGLLKCNT   KGLLKMOD   KGLLKREQ KGLNAOBJ
------ ---------- ---------- ---------- ---------- ------------------------------------------------------------
   276       6518          0          0          2 5ce7869058
    84       6429          0          0          2 5ce7869058
   329      19358          0          0          2 5ce7869058
   342      37088          0          0          2 5ce7869058
   407      17734          0          0          2 5ce7869058
    74      26333          0          0          2 5ce7869058
...snipped..

Object name 5ce7869058 is not a typical schema object and seems to be an internal object. We need to identify the owner of the object and that might lead to some clues.

 Two ways to find the row in x$kglob:
1. Convert the handle address to HEX and pad it.
SQL>  select to_char(399021346904,'xxxxxxxxxxxxxx') from dual;   
5ce7869058

SQL> select kglnawon, kglnaobj from x$kglob where kglhdpar =hextoraw('0000005CE7869058');
KGLNAOWN KGLNAOBJ
-------- -------------------------
$BUILD$  5ce7869058

2. Join to x$kgllk.
SQL> select kglnaown, kglnaobj from x$kglob where kglhdadr in 
        ( select kgllkhdl from x$kgllk where kgllkreq >0);
KGLNAOWN KGLNAOBJ
-------- -------------------------
$BUILD$  5ce7869058

Interesting. These objects are owned by the user $BUILD$. But, there is no such database user and this object must be an internal object.

At this time, I took a few pstack samples of the process and tried to learn a bit more about the problem. Nothing too interesting, function call kglLockWait indicates that we are waiting for library cache lock.

# pstack 12485
#0  0x00007f42737d100a in semtimedop () from /lib64/libc.so.6
#1  0x000000000cda832d in sskgpwwait ()
#2  0x000000000cda5c98 in skgpwwait ()
#3  0x000000000c8f2bab in ksliwat ()
#4  0x000000000c8f1fb1 in kslwaitctx ()
#5  0x0000000000c00810 in ksfwaitctx ()
#6  0x0000000003b6765d in kglLockWait ()
#7  0x000000000cdcd441 in kgllkal ()
#8  0x000000000cdc53e4 in kglLock ()
#9  0x000000000cdbeb32 in kglget ()
#10 0x000000000cb7650c in kksfbc ()
#11 0x000000000cb166ec in opiexe ()
#12 0x00000000021ee529 in kpoal8 ()
#13 0x000000000cb1254d in opiodr ()
#14 0x0000000003117d7e in kpoodr ()
#15 0x000000000cd41b4a in upirtrc ()
#16 0x000000000cd2cde6 in kpurcsc ()
#17 0x000000000cd28014 in kpuexec ()
#18 0x000000000cd420e9 in OCIStmtExecute ()
#19 0x0000000002073a10 in kxfxsStmtExecute ()
#20 0x0000000002073387 in kxfxsExecute ()
#21 0x000000000206df42 in kxfxsp ()
#22 0x000000000206c489 in kxfxmai ()
#23 0x00000000020a91b3 in kxfprdp ()
#24 0x00000000031014a6 in opirip ()
#25 0x0000000001bb0a08 in opidrv ()
#26 0x00000000026c0f71 in sou2o ()
#27 0x0000000000bbd85e in opimai_real ()
#28 0x00000000026cb6bc in ssthrdmain ()
#29 0x0000000000bbd72c in main ()

Conclusion

At this time, I have some information. So, I searched for ‘library cache lock $BUILD$’ in support.oracle.com and of course, found a bug matching with my symptoms. Further investigation from BDE confirmed my analysis. I didn’t want to list the bug numbers as similar symptom may have different root cause. So, you need to work with support further.

Posted in 12c, inmemory, Oracle database internals, Performance tuning, RAC | Tagged: , , , , , , , | 2 Comments »

OTNYathra2016

Posted by Riyaj Shamsudeen on March 24, 2016

Over the last many years, some of you have invited me to attend conferences in India, and talk about Oracle RAC and performance. I have not had an opportunity to make it to conferences in India, until now:)

I am excited to announce that I will be participating in OTN sponsored Oracle ACE Director’s tour in India (April 23rd to May 2nd 2016), and presenting ( with deep dive demos ) about RAC, performance, and in-memory. This is a golden opportunity for you to learn some of the internal stuff that I talk about in my class too.

Refer http://otnyathra.com for further details.

I am also excited to be in the tour with Connor McDonald, Biju Thomas, Sai, and many others. Don’t forget to send an email to Sai, the conference rooms will fill out quickly.

Did I mention deep dive demos?:)

Update 1: Updating the presentation slides and scripts. Do ask if I miss any script that you are looking for:)

india_2016_files_v1

Posted in 12c, Performance tuning, Presentations, RAC | Tagged: , | 5 Comments »

OOUG RAC day presentation files and scripts

Posted by Riyaj Shamsudeen on November 18, 2015

Thanks for coming to my presentations in RAC day at Dublin, Ohio. Please find the presentation files below. Hopefully, I will get video files and upload that here too.

OOUG presentation files and scripts

md5 checksum of the zip file is:

$md5sum ooug_2015_pdf.zip
df8bdcbc02926e5bbd721514b473bf16  ooug_2015_pdf.zip

Posted in Oracle database internals, Performance tuning, Presentations, RAC | Tagged: , , | 3 Comments »

RAC day with Ohio Oracle User Group

Posted by Riyaj Shamsudeen on October 22, 2015

I will be talking about RAC and performance in-depth, with lots of demos, in a RAC day training with Ohio Oracle User group on Nov 16,2015 Monday. Venue for the presentation is Dublin, Ohio.

Agenda for the day:

08:00a – 09:00: Registration / Breakfast

09:00a – 09:15: Announcements -Introduction of the speaker

09:15a – 10:30: Underpinning for Oracle RAC and Clusterware

10:30a – 10:45: Break

10:45a – 11:45: RAC cache fusion internals

11:45a – 01:00: Lunch

01:00p – 02:00: RAC Performance tuning Part 1 – Wait events and object tuning

02:00p – 02:15: Break

02:15p – 03:30: RAC performance tuning Part 2 – locks, library cache locks etc.

03:30p – 03:45: Member Announcements, Gift Drawings

Please RSVP to the co-ordinators so that you will have a seat:)

OOUG RAC day

Posted in Oracle database internals, Performance tuning, Presentations, RAC | Tagged: , , , | 1 Comment »

Demos do fail.

Posted by Riyaj Shamsudeen on April 15, 2015

I am an ardent believer of “show me how it works” principle and usually, I have demos in my presentation. So, I was presenting “Tools for advanced debugging in Solaris and Linux” with demos in IOUG Collaborate 2015 in Las Vegas on April 13 and my souped-up laptop (with 32G of memory, SSD drives, and an high end video processor etc ) was not responding when I tried to access folder to open my presentation files.

Sometimes, demos do fail. At least, I managed to complete the demos with zero slides:-) Apologies to the audience for my R-rated rants about laptop issues.

You can download presentations files from the links below.

Session_145_advanced_debugging_using_UNIX_tools

Session_189_Riyaj_Inmemory_internals_files

Posted in in-memory, inmemory, Performance tuning, Presentations | Tagged: , , , , , | Leave a Comment »

IOUG Collaborate 2015

Posted by Riyaj Shamsudeen on March 25, 2015

I will be presenting two topics in IOUG Collaborate 2015 in Vegas. Use the show planner and add my presentations to your schedule:)

Session #189: April 13 Monday 9:15 to 10:15AM Topic: Oracle Database 12c In-Memory Internals. Room Palm B

Session #145: April 13 Monday 12:45PM-1:45PM Topic: Tools and Techniques for Advanced Debugging in Solaris & Linux (mostly live demo). Room Palm B.

Posted in inmemory, Oracle database internals, Performance tuning, Presentations, RAC | Tagged: , , , , , | Leave a Comment »

RMOUG Training Days 2015

Posted by Riyaj Shamsudeen on January 19, 2015

I will be talking in Rocky Mountain Oracle User Group Training Days 2015( http://www.rmoug.org), with live demos (hopefully there will be no failures in the demo). My topics are:

Feb 17: Deep dive: 3:15PM to 5:15PM – RAC 12c optimization: I will discuss RAC global cache layer in detail with a few demos. You probably can’t find these deep Global Cache layer details anywhere else:)

Feb 19: Wednesday: 2:45PM to 3:45PM – Advanced UNIX tools: I will discuss both Solaris and Linux advanced tools to debug deep performance issues.

Feb 19: Wednesday: 12:15PM – 1:15PM – Exadata SIG panel with Alex Fatkulin.

Come to Denver. Come on, it won’t be cold ( I think:) )

Uploading presentation and scripts of the presentation files: RMOUG_2015_Riyaj_RAC_12c_optim files

Presentation files for Unix tools demos: RMOUG_2015_Riyaj_Unix_tools

Posted in 11g, 12c, Presentations, RAC | Tagged: , , , | 1 Comment »

In-memory pre-population speed

Posted by Riyaj Shamsudeen on October 6, 2014

While presenting at Oaktable World 2014 in San Fransisco, I discussed the in-memory pre-population speed and indicated that it takes about 30 minutes to 1 hour to load ~300GB of tables. Someone asked me “Why?” and that was a fair question. So, I profiled the in-memory pre-population at startup.

Profiling methods

I profiled all in-memory worker sessions using Tanel’s snapper script and also profiled the processes in OS using Linux perf tool with 99Hz sample rate. As there is no other activity in the database server, it is okay to sample everything in the server. Snapper output will indicate where the time is spent; if the time is spent executing in CPU, then the perf report output will tell us the function call stack executing at that CPU cycle. Data from these two profiling methods will help us to understand the root cause of slowness.

  1. @snapper.sql out,gather=stw 600 10 “select sid from v$session where program like ‘%W00%'”
  2. Perf tool : perf record -F 99 -u oracle -g sleep 3600

continue reading

Posted in 12c, in-memory, inmemory, Oracle database internals, Performance tuning, Presentations | Tagged: , , , , , , , | Leave a Comment »

Oaktable world 2014 is on!

Posted by Riyaj Shamsudeen on September 26, 2014

Many Oaktable members are planning to talk about deep technical topics in Oaktable world 2014. Looking at the agenda, I am excited, so many deep topics are planned. I will be talking about in-memory internals on Monday morning at 9AM, 9/29/2014, right after Mogens’ Keynote speech. You can find all details here: Oaktable world 2014. I will post my presentation slides after the presentation.

Start your open world week presentation with mine:). Sorry, no beers planned at that time, it is 9AM, after all!

Thanks for attending my presentation at Oaktable World 2014. You can download the slides : In-memory_internals.pdf.

Also, our book Expert Oracle RAC 12c has been translated to Chinese language. You can find details about that book in one of the translator’s blog: Alex lizx.

Posted in 12c, in-memory, inmemory | Tagged: , , | Leave a Comment »

inmemory: Why did that table was not populated in the column store?

Posted by Riyaj Shamsudeen on September 11, 2014

I enabled an huge 70G table for inmemory population, I expected the inmemory population to take a while, but the population didn’t complete even after letting it run for a day. Why?

ASH data

Initial review of the server shows no issues, no resource starvation. This must be a problem with Oracle processes itself. I started digging further, and ASH data shows that in numerous samples the process was seen reading block using single block I/I calls. Also object_id matches with the table I was trying to populate.

   select * from (
    select start_time, end_time, sql_id,event, current_obj#,  cnt_on_cpu + cnt_waiting tot_cnt,
  	rank () over ( order by (cnt_on_cpu + cnt_waiting) desc ) rnk
    from  (
    select
  	  min(start_time) start_time,
  	  max(end_time)   end_time,
  	  sql_id,event,current_obj#,
  	  sum(decode(session_state,'ON CPU',1,0))  cnt_on_cpu,
 	  sum(decode(session_state,'WAITING',1,0)) cnt_waiting
    from
     ( select
 	first_value(sample_time) over( order by sample_time ) start_time,
 	last_value(sample_time) over( order by sample_time
 				rows between unbounded preceding and unbounded following ) end_time,
 	sql_id,event, session_state, current_obj#
	from
 	     (select * from v$active_session_history ash where session_id= &&sid and session_serial#=&&serial_number)
     )
   group by sql_id, event, current_obj#
    )
  )
  where rnk 
/
START_TIME		  END_TIME		    SQL_ID	  EVENT 			 CURRENT_OBJ#	 TOT_CNT	RNK
------------------------- ------------------------- ------------- ------------------------------ ------------ ---------- ----------
18-AUG-14 08.42.03.702 AM 18-AUG-14 09.02.06.463 AM		  db file sequential read	       168967	     990	  1
												       168967	     156	  2
								  direct path read		       168967	      50	  3
						    bdwtqttka2w2y					   -1	       3	  4
						    bdwtqttka2w2y direct path read		       168967	       1	  5
						    24uqc4aqrhdrs				       168967	       1	  5
													   -1	       1	  5

Read the rest of this entry »

Posted in 12c, inmemory | Tagged: , | 3 Comments »

 
Follow

Get every new post delivered to your Inbox.

Join 282 other followers