Oracle database internals by Riyaj

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

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.

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

  1. Ray Man said

    How is it going with your blog? Are you posting and keeping it updated?

  2. Not even close ;-)

    I really, really need to work on my blog

  3. NR said

    Hi,
    Please keep posting. Looking forward to get more tips and info.

  4. Bommareddy said

    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?

  5. 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

  6. Taral Desai said

    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.

    • 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.

      • Taral Desai said

        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

      • 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

  7. Taral Desai said

    It’s a san storage.

  8. Taral Desai said

    It’s SAN

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

 
Follow

Get every new post delivered to your Inbox.

Join 214 other followers

%d bloggers like this: