At last, my blog is up.

Posted by Riyaj Shamsudeen on January 9, 2007

This has been one of my long pending wishes to have a blog and update it regularly.

I am an Oracle Database Administrator and I specialize in Oracle database internals and performance tuning. My emphasis currently in Real Application Clusters and E-Business Suite.

Hopefully, I will keep this blog updated and love to hear your comments.

I have also written couple of articles, presented few and will upload them here soon.

This entry was posted on January 9, 2007 at 9:32 pm and is filed under Uncategorized. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.

11 Responses to “At last, my blog is up.”

Ray Man said

February 5, 2007 at 5:40 am
How is it going with your blog? Are you posting and keeping it updated?

Reply
orainternals said

January 14, 2008 at 5:28 am
Not even close 😉

I really, really need to work on my blog

Reply
NR said

March 21, 2008 at 3:07 pm
Hi,
Please keep posting. Looking forward to get more tips and info.

Reply
Bommareddy said

July 23, 2008 at 10:00 pm
Hi I have a quick question for you. Hope you can reply me. In one of SQL Explain Plan I find lot of time spent on view SYS.VW_SQ_1 which is no where mention in the actual query, but does it appear in Explain Plan?

Reply
orainternals said

July 23, 2008 at 11:18 pm
Hello Bommareddy
Thanks for visiting my blog. vw_sq_1 indicates that your SQL has been rewritten. If you can create a small test case or your SQL and post it here, may be I can confirm that..

Cheers
Riyaj

Reply

Taral Desai said

May 11, 2009 at 10:59 pm

Hi Riyaj,

Sorry to write it here but don’t know where to write so here is my problem. Can you please help me resolving this

1. Environment SunOS qapqdb04 5.10 Generic_127127-11 sun4u sparc SUNW,SPARC-Enterprise. 10.2.3 on SPARC 64 Bit

2. We are observing wait event ‘db file init write’ when we add any datafile.
3. Here is the truss output of the process waiting on this event

Base time stamp:  1242076765.4851  [ Mon May 11 17:19:25 EDT 2009 ]
/5:	 0.0545	kaio(AIONOTIFY, 0)				= 0
/11:	 0.0545	kaio(AIONOTIFY, 0)				= 0
/9:	 0.0548	kaio(AIONOTIFY, 0)				= 0
/1:	 0.0550	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/7:	 0.0550	kaio(AIONOTIFY, 0)				= 0
/1:	 0.0559	lwp_unpark(9)					= 0
/9:	 0.0559	lwp_park(0x00000000, 0)				= 0
/11:	 0.0567	lwp_park(0x00000000, 0)				= 0
/1:	 0.0567	lwp_unpark(11)					= 0
/1:	 0.0579	lwp_unpark(5)					= 0
/5:	 0.0579	lwp_park(0x00000000, 0)				= 0
/1:	 0.0589	lwp_unpark(7)					= 0
/7:	 0.0589	lwp_park(0x00000000, 0)				= 0
/1:	 0.0590	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.0591	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.0591	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/9:	 0.0620	pwrite(259, "E218B8C0".., 1048576, 0xC5C600000) = 1048576
/9:	 0.0622	kaio(AIONOTIFY, 0)				= 0
/1:	 0.0622	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.0624	lwp_unpark(9)					= 0
/9:	 0.0625	lwp_park(0x00000000, 0)				= 0
/11:	 0.0843	pwrite(259, "E218B8E0".., 1048576, 0xC5C700000) = 1048576
/11:	 0.0845	kaio(AIONOTIFY, 0)				= 0
/1:	 0.0845	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.0855	lwp_unpark(11)					= 0
/11:	 0.0855	lwp_park(0x00000000, 0)				= 0
/5:	 0.0900	pwrite(259, "E218B9".., 1048576, 0xC5C800000) = 1048576
/5:	 0.0901	kaio(AIONOTIFY, 0)				= 0
/1:	 0.0901	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.0904	lwp_unpark(5)					= 0
/5:	 0.0904	lwp_park(0x00000000, 0)				= 0
/7:	 0.1141	pwrite(259, "E218B9  ".., 1048576, 0xC5C900000) = 1048576
/7:	 0.1144	kaio(AIONOTIFY, 0)				= 0
/1:	 0.1145	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.1153	lwp_unpark(7)					= 0
/7:	 0.1154	lwp_park(0x00000000, 0)				= 0
/9:	 0.1204	pwrite(259, "E218B9 @".., 1048576, 0xC5CA00000) = 1048576
/9:	 0.1205	kaio(AIONOTIFY, 0)				= 0
/1:	 0.1206	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.1218	lwp_unpark(9)					= 0
/9:	 0.1218	lwp_park(0x00000000, 0)				= 0
/11:	 0.1442	pwrite(259, "E218B9 `".., 1048576, 0xC5CB00000) = 1048576
/11:	 0.1445	kaio(AIONOTIFY, 0)				= 0
/1:	 0.1445	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.1453	lwp_unpark(11)					= 0
/11:	 0.1454	lwp_park(0x00000000, 0)				= 0
/5:	 0.1641	pwrite(259, "E218B980".., 1048576, 0xC5CC00000) = 1048576
/5:	 0.1643	kaio(AIONOTIFY, 0)				= 0
/1:	 0.1643	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.1655	lwp_unpark(5)					= 0
/5:	 0.1655	lwp_park(0x00000000, 0)				= 0
/7:	 0.1841	pwrite(259, "E218B9A0".., 1048576, 0xC5CD00000) = 1048576
/7:	 0.1844	kaio(AIONOTIFY, 0)				= 0
/1:	 0.1844	kaio(AIOWAIT, 0xFFFFFFFF7FFF7200)		= 1
/1:	 0.1854	lwp_unpark(7)					= 0
/7:	 0.1854	lwp_park(0x00000000, 0)				= 0
/9:	 0.2041	pwrite(259, "E218B9C0".., 1048576, 0xC5CE00000) = 1048576

4. This is from one of the dbwriter process

/1:      2.6303 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:      2.6308 times(0xFFFFFFFF7FFFDDE0)                       = 632454879
/1:      2.6309 times(0xFFFFFFFF7FFFDD30)                       = 632454879
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:      5.6403 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:      8.6503 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:      8.6508 times(0xFFFFFFFF7FFFDDE0)                       = 632455481
/1:      8.6509 times(0xFFFFFFFF7FFFDD30)                       = 632455481
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     11.6604 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     14.6704 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     14.6708 times(0xFFFFFFFF7FFFDDE0)                       = 632456083
/1:     14.6709 times(0xFFFFFFFF7FFFDD30)                       = 632456083
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     17.6804 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     20.6904 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     20.6908 times(0xFFFFFFFF7FFFDDE0)                       = 632456685
/1:     20.6909 times(0xFFFFFFFF7FFFDD30)                       = 632456685
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     23.7003 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     26.7104 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     26.7108 times(0xFFFFFFFF7FFFDDE0)                       = 632457287
/1:     26.7112 times(0xFFFFFFFF7FFFDD30)                       = 632457287
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)
/1:     29.7203 semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) Err#11 EAGAIN
/1:     semtimedop(16777249, 0xFFFFFFFF7FFFDBF4, 1, 0xFFFFFFFF7FFFDBE0) (sleeping...)

5. short stack of the process from oracle

ksdxfstk()+36<-ksdxcb()+2452<-sspuser()+176<-__sighndlr()+12<-call_user_handler()+992<-aiowait()+540<-skgfospo()+592<-skgfrwat()+80<-ksfdwtio()+568<-ksfdwat1()+84<-ksfdrwat0()+568<-ksfqwat()+160<-ksfqgbuf()+536<-kcflfi()+500<-kcfcedtf()+376<-tbsafl()+832<-atsdrv()+8000<-opiexe()+20568<-opiosq0()+4436<-kpooprx()+216<-kpoal8()+696<-opiodr()+1548<-ttcpip()+1284<-opitsk()+1432<-opiino()+1128<-opiodr()+1548<-opidrv()+896<-sou2o()+80<-opimai_real()+124<-main()+152<-_start()+380

6. truss for the process again that is adding datafile(summary)

syscall               seconds   calls  errors
lwp_park                 .020     968
lwp_unpark               .020     968
pwrite                  5.913     968
kaio                     .029     967
kaio                     .017     967
                     --------  ------   ----
sys totals:             6.000    4838      0
usr time:                .703
elapsed:               17.220

Can you please help identifying problem.

orainternals said

May 12, 2009 at 2:33 pm
Taral
When a datafile is added or a non-temporary tablespace created, session performing that activity, will initialize every block in that data file. So, if you add, 20GB data file, then 20GB of data must be written to that new data file. That is just a normal operation. After submitting I/O, session will wait for ‘db file init write’ wait event. It is normal for that session to wait for ‘db file init write’ event and other sessions should not wait for that event though.

It is possible to have performance issues while creating data file or adding a data file due to this massive I/O activity. Are you trying to debug a performance issue? or Are you trying to improve performance of creating tablespace or adding data file?

Now, this comment is not applicable to tempfiles. Temporary tablespace files (created with ‘create temporary tablepace’) are sparse files (9i+) and only few blocks in each files need to be initialized for tempfiles.

Reply
- Taral Desai said
  
  May 12, 2009 at 4:02 pm
  Hi Riyaj,
  
  I am trying to debug a performance issue. Because for other servers we have won’t take too long.
  
  Before couple of days i had tested for adding 100MB in one server(Good) and here is the comparison. Here is some abstract.
  
  ==========================
  BAD
  /7: 1.4889 pwrite(259, “C201”.., 1032192, 16384) = 1032192
  /1: 1.4922 lwp_unpark(9) = 0
  /9: 1.4923 lwp_park(0x00000000, 0) = 0
  /1: 1.4975 lwp_unpark(10) = 0
  /10: 1.4975 lwp_park(0x00000000, 0) = 0
  /1: 1.5008 lwp_unpark(7) = 0
  /7: 1.5008 lwp_park(0x00000000, 0) = 0
  /8: 1.8134 pwrite(259, “C2 @”.., 1048576, 1048576) = 1048576
  /8: 1.8136 kaio(AIONOTIFY, 0) = 0
  /1: 1.8136 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /1: 1.8155 lwp_unpark(8) = 0
  /8: 1.8155 lwp_park(0x00000000, 0) = 0
  /3: lwp_park(0x00000000, 0) (sleeping…)
  /4: lwp_park(0x00000000, 0) (sleeping…)
  /5: lwp_park(0x00000000, 0) (sleeping…)
  /6: lwp_park(0x00000000, 0) (sleeping…)
  /2: kaio(6, 0x00000000, 0xFFFFFFFF7C0F7F00, 0x00000010, 0xFFFFFFFF7C0F8F58, 0xFFFFFFFF7C200A00) (sleeping…)
  /11: lwp_park(0x00000000, 0) (sleeping…)
  /9: 2.5424 pwrite(259, “C280”.., 1048576, 2097152) = 1048576
  /9: 2.5426 kaio(AIONOTIFY, 0) = 0
  /1: 2.5426 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /1: 2.5459 lwp_unpark(9) = 0
  /9: 2.5459 lwp_park(0x00000000, 0) = 0
  /10: 2.8614 pwrite(259, “C2C0”.., 1048576, 3145728) = 1048576
  /10: 2.8616 kaio(AIONOTIFY, 0) = 0
  /1: 2.8617 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /10: 2.8649 lwp_park(0x00000000, 0) = 0
  /1: 2.8649 lwp_unpark(10) = 0
  /7: 3.1660 pwrite(259, “C201”.., 1048576, 4194304) = 1048576
  ========================================================================================
  I Think Good
  
  /7: 3.0600 pwrite(260, “C201”.., 1032192, 16384) = 1032192
  /7: 3.0605 kaio(AIONOTIFY, 0) = 0
  /1: 3.0605 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /1: 3.0618 lwp_unpark(7) = 0
  /7: 3.0618 lwp_park(0x00000000, 0) = 0
  /8: 3.0797 pwrite(260, “C2 @”.., 1048576, 1048576) = 1048576
  /8: 3.0799 kaio(AIONOTIFY, 0) = 0
  /1: 3.0799 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /1: 3.0812 lwp_unpark(8) = 0
  /8: 3.0812 lwp_park(0x00000000, 0) = 0
  /9: 3.0845 pwrite(260, “C280”.., 1048576, 2097152) = 1048576
  /9: 3.0847 kaio(AIONOTIFY, 0) = 0
  /1: 3.0847 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /1: 3.0858 lwp_unpark(9) = 0
  /9: 3.0858 lwp_park(0x00000000, 0) = 0
  /10: 3.1001 pwrite(260, “C2C0”.., 1048576, 3145728) = 1048576
  /10: 3.1005 kaio(AIONOTIFY, 0) = 0
  /1: 3.1005 kaio(AIOWAIT, 0xFFFFFFFF7FFF7BC0) = 1
  /1: 3.1016 lwp_unpark(10) = 0
  /10: 3.1016 lwp_park(0x00000000, 0) = 0
  /7: 3.1196 pwrite(260, “C201”.., 1048576, 4194304) = 1048576
- orainternals said
  
  May 13, 2009 at 2:18 am
  Hello Taral
  From the lines tagged as BAD, write calls for 1MB of data took 119ms, 21ms, 35ms and 35ms respectively.
  For GOOD case, it took 18ms, 15ms, 13ms and 15ms respectively.
  It is obvious that BAD case has write performance issue. What type of storage sub-systems are these two cases? I think, I can take a guess: -) but I would rather hear it from you.
  
  BAD
  /7: 1.4889 pwrite(259, “C201”.., 1032192, 16384) = 1032192
  /7: 1.5008 lwp_park(0x00000000, 0) = 0
  
  119ms
  
  /8: 1.8134 pwrite(259, “C2 @”.., 1048576, 1048576) = 1048576
  /8: 1.8155 lwp_park(0x00000000, 0) = 0
  21ms
  
  /9: 2.5424 pwrite(259, “C280”.., 1048576, 2097152) = 1048576
  /9: 2.5459 lwp_park(0×00000000, 0) = 0
  35ms
  
  /10: 2.8614 pwrite(259, “C2C0”.., 1048576, 3145728) = 1048576
  /10: 2.8649 lwp_park(0x00000000, 0) = 0
  
  35ms
  
  ========================================================================================
  I Think Good
  
  /7: 3.0600 pwrite(260, “C201”.., 1032192, 16384) = 1032192
  /7: 3.0618 lwp_park(0x00000000, 0) = 0
  18ms
  
  /8: 3.0797 pwrite(260, “C2 @”.., 1048576, 1048576) = 1048576
  /8: 3.0812 lwp_park(0x00000000, 0) = 0
  15ms
  
  /9: 3.0845 pwrite(260, “C280”.., 1048576, 2097152) = 1048576
  /9: 3.0858 lwp_park(0x00000000, 0) = 0
  13ms
  
  /10: 3.1001 pwrite(260, “C2C0”.., 1048576, 3145728) = 1048576
  /10: 3.1016 lwp_park(0x00000000, 0) = 0
  15ms

Taral Desai said

May 13, 2009 at 2:43 am
It’s a san storage.

Reply
Taral Desai said

May 13, 2009 at 2:08 pm
It’s SAN

Reply

Oracle database internals by Riyaj

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

Categories

Archives

Click image for details:

Links for training, scripts etc

Blogroll oracle

Blogroll