Re: Reading resource busy error system trace

Thank You. It's a third party app code so it is not easy to ask for this change in code.

So Is there any down side or is it okay , if we set the ddl_lock_timeout as say 300 i.e. (~5 minutes) in system level. Something as below? I hope it will take immediate effect without an instance restart.

Alter system set ddl_lock_timeout=300 SCOPE=BOTH SID= '*';

On Mon, Jul 4, 2022 at 10:25 AM Lok P <loknath.73_at_gmail.com> wrote:

> As you stated it reruns fine after a couple of attempts without any
> change. And if it's just the buggy behaviour in which Oracle is not
> releasing the locks from the table, immediately post COMMIT after direct
> path load but after sometime it releases, maybe because of higher database
> load during that time etc. Then, probably you would like to set the
> ddl_lock_timeout to a minute or more and see if it's completing fine, as
> the ALTER will keep waiting for that amount of time before throwing out a
> ora- 0054.
>
> On Sun, Jul 3, 2022 at 3:13 PM Pap <oracle.developer35_at_gmail.com> wrote:
>
>> No. Actually we were not performing any DML on any of the reference
>> tables nor on the same table. That is why we end up setting the trace to
>> see what exact session is blocking and making the ALTER fail. And again if
>> it is the DML on the reference table causing this then the trace should
>> have pointed to the other blocking pid/session rather pointing to the same
>> session which had endup in ora-0054.
>>
>> And yes you are correct , as per the trace it's saying the same session
>> blocking itself(ALTER statement) post direct path load (loading ~200milion
>> rows) + commit, which is kind of odd. And also surprisingly this same code
>> fails a couple of times and then succeeds on its own after multiple rerun
>> without any other change. And I notice , this failure is happening during
>> the days with high volume load only.
>>
>> On Sun, Jul 3, 2022 at 2:44 PM Lok P <loknath.73_at_gmail.com> wrote:
>>
>>> It looks really strange which you have pointed in the trace file though.
>>> Correct me if wrong, So your blocking session/pid for the 'ALTER' statement
>>> in the trace is pointing to the same session. And that session has just
>>> ended up doing direct path load by post disabling constraints/indexes and
>>> is trying to enable the constraints using ALTER command and is failing with
>>> Ora-0054. And that to post committing the direct load data. Just a thought,
>>> are you doing any DML on the parent table which is linked to this
>>> reference constraint which you are trying to enable here?
>>>
>>> On Sat, Jul 2, 2022 at 11:27 PM Pap <oracle.developer35_at_gmail.com>
>>> wrote:
>>>
>>>> Hello All, I followed the blog below and tried debugging the system
>>>> trace to find the blocking session/sql which caused this resource busy
>>>> error, Ora-0054. But I am encountering strange behaviour. It appears to be
>>>> the same session blocking itself.The session which did the direct path load
>>>> and commit seems not releasing exclusive lock for some duration post
>>>> commit. Below are the details of the behaviour. Has anybody
>>>> encountered such a scenario?
>>>>
>>>>
>>>> https://nenadnoveljic.com/blog/troubleshooting-ora-00054-resource-busy-and-acquire-with-nowait-specified-or-timeout-expired/
>>>>
>>>> So the code which is encountering the error is below. Its disabling all
>>>> constraints + Making index unusable and then does direct path load to that
>>>> table and then after while trying to enable the constraint of the same
>>>> table using 'ALTER' and its failing with Ora-0054. The sample code for data
>>>> load and ALTER table is as below.
>>>>
>>>> ****Sample code *****
>>>> INSERT /*+Append*/ INTO TAB1 (c1,c2.....)
>>>> SELECT (ROWNUM + sqq_key) ,col1, col2, col3..... from....tab2,
>>>> tab3, tab4.....;
>>>> COMMIT;
>>>>
>>>> FOR I IN (SELECT TABLE_NAME, CONSTRAINT_NAME FROM ALL_CONSTRAINTS WHERE
>>>> TABLE_NAME = v_table_nm AND CONSTRAINT_TYPE = 'R' AND STATUS = 'DISABLED')
>>>> LOOP
>>>> EXECUTE IMMEDIATE ('ALTER TABLE ' || v_table_nm || ' ENABLE
>>>> NOVALIDATE CONSTRAINT '|| I.CONSTRAINT_NAME);
>>>> END LOOP I;
>>>>
>>>> ********
>>>>
>>>> When i scan through trace file as per the blog step by step, i see below
>>>>
>>>> *Step- 1 -* I searched through the object_Id(101739) for TAB1 and got
>>>> the section below, i.e pointing towards a DML lock on the table. And the
>>>> process state object is proc: 0x243efffc0.
>>>>
>>>> ----------------------------------------
>>>> SO: 0x233cd8bc8, type: DML lock (83), map: 0x237d28a10
>>>> state: LIVE (0x4532), flags: 0x0
>>>> owner: 0x233b9af60, proc: 0x243efffc0
>>>> link: 0x233cd8be8[0x28acf1e58, 0x1d793c780]
>>>> pg: 0
>>>> SOC: 0x237d28a10, type: *DML lock* (83), map: 0x233cd8bc8
>>>> state: LIVE (0x99fc), flags: INIT (0x1)
>>>> DML LOCK: tab=101739 flg=11 chi=0
>>>> his[0]: mod=4 spn=69302
>>>> 2022-07-01 05:44:10.662*:ksq.c_at_10787:ksqdmc(): Enqueue Dump
>>>> (enqueue) TM-00018D6B-00000000-00000000-00000000 DID: ksqlkdid:
>>>> 0001-00CF-000ACD5C
>>>> lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x7
>>>> mode: S, lock_flag: 0x20, lock: 0x237d28a38, res: 0x2499f3798
>>>> own: 0x2488605f8, sess: 0x2488605f8, *proc: 0x2403a4510*, prv:
>>>> 0x2499f37a8
>>>> slk: 0x2530967c8
>>>> ----------------------------------------
>>>>
>>>>
>>>> *STEP - 2:-* Then i searched through the trace for the state object
>>>> address i.e. "*SO: 0x243efffc0*" and got below. its pointing to
>>>> pid:207 as below.
>>>>
>>>>
>>>> *** 2022-07-01T05:44:10.538156-04:00
>>>> PROCESS 207:
>>>> ----------------------------------------
>>>> *SO: 0x243efffc0*, type: process (2), map: 0x2403a4510
>>>> state: LIVE (0x4532), flags: 0x1
>>>> owner: (nil), proc: 0x243efffc0
>>>> link: 0x243efffe0[0x243efffe0, 0x243efffe0]
>>>> child list count: 15, link: 0x243f00030[0x243b7f190, 0x1d7903b10]
>>>> pg: 0
>>>> SOC: 0x2403a4510, type: process (2), map: 0x243efffc0
>>>> state: LIVE (0x99fc), flags: INIT (0x1)
>>>> (process) *Oracle pid:207,* ser:3445, calls cur/top:
>>>> 0x1a0372f08/0x1d2ee6c70
>>>> flags : (0x0) - icon_uid:0 logon_pdbid=0
>>>> flags2: (0x1000), flags3: (0x510)
>>>> call error: 0, sess error: 0, txn error 0
>>>> intr queue: empty
>>>> (post info) last post received: 0 0 277
>>>> last post received-location: kcl2.h LINE:5703 ID:kclcget
>>>> last process to post me: 0x24c3b2180 1 6
>>>> last post sent: 0 0 33
>>>> last post sent-location: ksa2.h LINE:298 ID:ksasnd
>>>> last process posted by me: 0x24837eaa0 1 6
>>>> waiter on post event: 0
>>>> (latch info) hold_bits=0x0 ud_influx=0x4101b
>>>> (osp latch info) hold_bits=0x0 ud_influx=0x0
>>>> Process Group: DEFAULT, pseudo proc: 0x2484c5d70
>>>> O/S info: user: grid, term: UNKNOWN, ospid: 383076
>>>> OSD pid info:
>>>> Short stack dump:
>>>>
>>>> ksedsts()+426<-ksdxfstk()+58<-ksdxdocmdmultex()+5961<-ksdxdocmdmult()+55<-ksudmp_proc()+1626<-ksudss_main()+1976<-ksudss_opt()+1544<-dbkdaKsdActDriver()+2484<-dbgdaExecuteAction()+354<-dbgdaRunAction()+770<-dbgdRunActions()+83<-dbgdProcessEventActions()+525<-dbgdChkEventKgErr()+394<-dbkdChkEventRdbmsErr()+65<-dbgePostErrorKGE()+1066<-dbkePostKGE_kgsf()+71<-kgeade()+338<-kgeselv()+89<-ksesecl0()+189<-ktaiam()+1110<-ktagetg0()+929<-ktagetp_internal()+141<-ktagetg_ddlX()+323<-ktagetg_ddl()+30<-kkdllk0()+1551<-kkdcprc()+711<-kkdcmco()+3682<-atbadd()+8770<-atbdrv()+14663<-opiexe()+30061<-opiosq0()+4575<-opipls()+14619<-opiodr()+1202<-rpidrus()+198<-skgmstack()+65<-rpidru()+132<-rpiswu2()+614<-rpidrv()+1494<-psddr0()+467<-psdnal()+646<-pevm_EXIM()+276<-pfrinstr_EXIM()+43<-pfrrun_no_tool()+52<-pfrrun()+902<-plsql_run()+755<-peicnt()+279<-kkxexe()+720<-opiexe()+24762<-kpoal8()+2226<-opiodr()+1202<-ttcpip()+1239<-opitsk()+1897<-opiino()+936<-opiodr()+1202<-opidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245
>>>>
>>>> KGL-UOL (Process state object)
>>>> KGX Atomic Operation Log 0x2403a5690
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a56f8
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a5760
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a57c8
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a5830
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a5898
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a5900
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a5968
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> KGX Atomic Operation Log 0x2403a59d0
>>>> Mutex (nil)(0, 0) idn 0 oper NONE(0)
>>>> FSO mutex uid 262142 efd 0 whr 0 slp 0
>>>> ----------------------------------------
>>>>
>>>>
>>>> *Step-3 :- * Then searching for the *pid-207* in the start of the
>>>> trace , i found *sid - 1072 ser 23 *and its pointing to the same ALTER
>>>> TABLE statement. The OSPID is the same one for which the trace gets
>>>> generated. And if I try to see the DML in this sesion before this ALTER
>>>> it's the same one, which has just finished up doing the COMMIT for the
>>>> direct path load.
>>>>
>>>> So I am wondering , is it possible that we are hitting any bug due to
>>>> which Oracle is actually not releasing the Exclusive table lock immediately
>>>> post Commit of the direct path load ? And that is why , even if we are
>>>> trying to do the ALTER post COMMIT in the same session we are hitting
>>>> Ora-0054 as it blocks itself? And then should we put some wait/sleep
>>>> statement post commit i.e. before the ALTER to avoid this bug?
>>>>
>>>> 207: USER ospid 383076 sid 1072 ser 23,
>>>> Cmd: ALTER TABLE
>>>>
>>>> On Mon, Jun 13, 2022 at 4:28 PM Pap <oracle.developer35_at_gmail.com>
>>>> wrote:
>>>>
>>>>> Thank You So much Nenad.
>>>>>
>>>>> Unfortunately while checking with the team got to know that the other
>>>>> trace files has been removed from the location. So i will wait for the next
>>>>> occurrence of the error to capture and analyze all the traces wrt that one
>>>>> ospid.
>>>>>
>>>>>
>>>>> On Sun, 12 Jun 2022, 9:24 pm Noveljic Nenad, <
>>>>> nenad.noveljic_at_vontobel.com> wrote:
>>>>>
>>>>>> Your system dump apparently consists of several files.
>>>>>>
>>>>>>
>>>>>>
>>>>>> At the very beginning of the system dump there must be a section that
>>>>>> identifies the blockers for each process and looks something like this:
>>>>>>
>>>>>> 157: USER ospid 1385877 sid 786 ser 49681, waiting for 'log file
>>>>>> switch (checkpoint incomplete)'
>>>>>>
>>>>>> Cmd: INSERT
>>>>>>
>>>>>> Blocked by inst: 1, sid: 266, ser: 13238
>>>>>>
>>>>>> Final Blocker inst: 1, sid: 266, ser: 13238
>>>>>>
>>>>>> 159: USER ospid 1295896 sid 796 ser 48963, waiting for 'log file
>>>>>> switch (checkpoint incomplete)'
>>>>>>
>>>>>> Cmd: INSERT
>>>>>>
>>>>>> Blocked by inst: 1, sid: 266, ser: 13238
>>>>>>
>>>>>> Final Blocker inst: 1, sid: 266, ser: 13238
>>>>>>
>>>>>>
>>>>>>
>>>>>> First, check who was blocking the Powercenter process with ospid 89092
>>>>>> (Blocked by…). Then search **all** system dump trace files (**89092**.trc)
>>>>>> for the blocker to look at its state objects. Once you now the sid and
>>>>>> serial of the blocker, you can position yourself to its state objects with
>>>>>> the following search expression: sid: xxx ser: xxx . One of the state
>>>>>> objects will be for the cursor that blocked your DDL on MAIN_TAB.
>>>>>>
>>>>>>
>>>>>>
>>>>>> Best regards,
>>>>>>
>>>>>>
>>>>>>
>>>>>> Nenad
>>>>>>
>>>>>>
>>>>>>
>>>>>> *From:* Pap <oracle.developer35_at_gmail.com>
>>>>>> *Sent:* Sonntag, 12. Juni 2022 14:06
>>>>>> *To:* Noveljic Nenad <nenad.noveljic_at_vontobel.com>
>>>>>> *Cc:* Oracle L <oracle-l_at_freelists.org>
>>>>>> *Subject:* Re: Reading resource busy error system trace
>>>>>>
>>>>>>
>>>>>>
>>>>>> Thank You Nenad.
>>>>>>
>>>>>> So actually here the session/Alter statement, which failed, is from
>>>>>> the informatica power center session only. So do you mean we should search
>>>>>> the body of the original trace file from which this trace continued from
>>>>>> i.e "u01/app/oracle/diag/rdbms/DB1p/DB11/trace/DB11_ora_89092_8.trc"
>>>>>> rather this one. And in that trace the sql statements near the "final
>>>>>> blocker" string will be the cause of this error?
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> ____________________________________________________
>>>>>>
>>>>>> Please consider the environment before printing this e-mail.
>>>>>>
>>>>>> Bitte denken Sie an die Umwelt, bevor Sie dieses E-Mail drucken.
>>>>>>
>>>>>>
>>>>>> Important Notice
>>>>>>
>>>>>> This message is intended only for the individual named. It may
>>>>>> contain confidential or privileged information. If you are not the named
>>>>>> addressee you should in particular not disseminate, distribute, modify or
>>>>>> copy this e-mail. Please notify the sender immediately by e-mail, if you
>>>>>> have received this message by mistake and delete it from your system.
>>>>>> Without prejudice to any contractual agreements between you and us
>>>>>> which shall prevail in any case, we take it as your authorization to
>>>>>> correspond with you by e-mail if you send us messages by e-mail. However,
>>>>>> we reserve the right not to execute orders and instructions transmitted by
>>>>>> e-mail at any time and without further explanation.
>>>>>> E-mail transmission may not be secure or error-free as information
>>>>>> could be intercepted, corrupted, lost, destroyed, arrive late or
>>>>>> incomplete. Also processing of incoming e-mails cannot be guaranteed. All
>>>>>> liability of Vontobel Holding Ltd. and any of its affiliates (hereinafter
>>>>>> collectively referred to as "Vontobel Group") for any damages resulting
>>>>>> from e-mail use is excluded. You are advised that urgent and time sensitive
>>>>>> messages should not be sent by e-mail and if verification is required
>>>>>> please request a printed version.
>>>>>> Please note that all e-mail communications to and from the Vontobel
>>>>>> Group are subject to electronic storage and review by Vontobel Group.
>>>>>> Unless stated to the contrary and without prejudice to any contractual
>>>>>> agreements between you and Vontobel Group which shall prevail in any case,
>>>>>> e-mail-communication is for informational purposes only and is not intended
>>>>>> as an offer or solicitation for the purchase or sale of any financial
>>>>>> instrument or as an official confirmation of any transaction.
>>>>>> The legal basis for the processing of your personal data is the
>>>>>> legitimate interest to develop a commercial relationship with you, as well
>>>>>> as your consent to forward you commercial communications. You can exercise,
>>>>>> at any time and under the terms established under current regulation, your
>>>>>> rights. If you prefer not to receive any further communications, please
>>>>>> contact your client relationship manager if you are a client of Vontobel
>>>>>> Group or notify the sender. Please note for an exact reference to the
>>>>>> affected group entity the corporate e-mail signature. For further
>>>>>> information about data privacy at Vontobel Group please consult
>>>>>> www.vontobel.com.
>>>>>>
>>>>>

--
http://www.freelists.org/webpage/oracle-l