7 Replies Latest reply on Oct 13, 2014 4:08 PM by Jonathan Lewis

    Deadlock Graph- help required

    VivekSree

      I am trying to post this question multiple times, as the question is getting deleted automatically, not sure because its posted to other forums as well.

      I have removed the question from other groups, to avoid duplication, which I had posted, and this is the only one active.

      So I would request the administrator of the group to not delete this question without answering it.

       

      I am trying to root-cause a deadlock issue.

      I have few questions regarding the same:

      • How to find which is the Resource involved in the Deadlock?
        • I already checked using the SQL command - select object_name,owner,data_object_id from dba_objects where data_object_id=39341
          • I get no rows when I run that.
      • From Resource Name what can be deciphered?

       

      The inserts are all ordered by value of the primary key, but still we are ending up with Deadlock. Could this be due to Lock on Unique Key constraint

      If yes, how to find out whether this is a lock acquired on Table - DeviceDetails OR on the Unique Key constraint of the table DeviceDetails?

      Under what scenarios would "S" lock mode be used? We are not using select for update anywhere, and anyway, this seems to be insert statements as per the graph below.

       

      DEADLOCK DETECTED ( ORA-00060 )

       

      [Transaction Deadlock]

       

      The following deadlock is not an ORACLE error. It is a

      deadlock due to user error in the design of an application

      or from issuing incorrect ad-hoc SQL. The following

      information may aid in determining the deadlock:

       

      Deadlock graph:

                             ---------Blocker(s)--------  ---------Waiter(s)---------

      Resource Name          process session holds waits  process session holds waits

      TX-0007001f-000131c5        38     486     X             47     731           S

      TX-00020005-000131f6        47     731     X             38     486           S

       

      session 486: DID 0001-0026-000000E2 session 731: DID 0001-002F-0000001B

      session 731: DID 0001-002F-0000001B session 486: DID 0001-0026-000000E2

       

      Rows waited on:

        Session 486: obj - rowid = 000099AD - AAAJ4xAAKAAACgrAAA

        (dictionary objn - 39341, file - 10, block - 10283, slot - 0)

        Session 731: obj - rowid = 000099AD - AAAJ4xAAKAAACgrAAA

        (dictionary objn - 39341, file - 10, block - 10283, slot - 0)

       

      ----- Information for the OTHER waiting sessions -----

      Session 731:

        sid: 731 ser: 1603 audsid: 896907 user: 37/user1

          flags: (0x8000045) USR/- flags_idl: (0x1) BSY/-/-/-/-/-

          flags2: (0x40009) -/-/INC

        pid: 47 O/S info: user: oracle, term: UNKNOWN, ospid: 22799

          image: oracle@term7252

        client details:

          O/S info: user: root, term: unknown, ospid: 1234

          machine: term7252 program: JDBC Thin Client

          application name: JDBC Thin Client, hash value=2546894660

        current SQL:

        insert into DeviceDetails (INSTANCE_VERSION, term2, lastModifiedAt, term3DiscoveredFrom, hostUserName, profile, userPassword, description, lifeTime, startTime, endTime, campus, building, floorArea, outdoorArea, configGroup, emailID, disclaimerText, startDate, endDate, weekDays, ishostUser, applyUserTo, serviceDomainId, isScheduledUser, userStatus, isNewUserName, validity, isDefaultEditable, userRole, createdBy, createdAt, term6, rebootterm4, term1Years, term1Months, term1Days, term1Hours, term1Mins, term1Secs, isPasswordEncr, attributeList, term1StartTime, term1FirstLoginTime, term5EntityId, term5EntityClass, id) values (:1 , :2 , :3 , :4 , :5 , :6 , :7 , :8 , :9 , :10 , :11 , :12 , :13 , :14 , :15 , :16 , :17 , :18 , :19 , :20 , :21 , :22 , :23 , :24 , :25 , :26 , :27 ,

       

      ----- End of information for the OTHER waiting sessions -----

       

      Information for THIS session:

       

      ----- Current SQL Statement for this session (sql_id=dnj1vu47agct7) -----

      insert into DeviceDetails (INSTANCE_VERSION, term2, lastModifiedAt, term3DiscoveredFrom, hostUserName, profile, userPassword, description, lifeTime, startTime, endTime, campus, building, floorArea, outdoorArea, configGroup, emailID, disclaimerText, startDate, endDate, weekDays, ishostUser, applyUserTo, serviceDomainId, isScheduledUser, userStatus, isNewUserName, validity, isDefaultEditable, userRole, createdBy, createdAt, term6, rebootterm4, term1Years, term1Months, term1Days, term1Hours, term1Mins, term1Secs, isPasswordEncr, attributeList, term1StartTime, term1FirstLoginTime, term5EntityId, term5EntityClass, id) values (:1 , :2 , :3 , :4 , :5 , :6 , :7 , :8 , :9 , :10 , :11 , :12 , :13 , :14 , :15 , :16 , :17 , :18 , :19 , :20 , :21 , :22 , :23 , :24 , :25 , :26 , :27 , :28 , :29 , :30 , :31 , :32 , :33 , :34 , :35 , :36 , :37 , :38 , :39 , :40 , :41 , :42 , :43 , :44 , :45 , :46 , :47 )

      ===================================================

        • 1. Re: Deadlock Graph- help required
          Etbin
          1 person found this helpful
          • 2. Re: Deadlock Graph- help required
            VivekSree

            I needed some explanation as to when would the waits show "S" or shared mode.

            Going through multiple threads, it seems it could be in two cases, for insert statements involved in the Deadlock:

            • Lock on Unique Key constraint
            • OR - ITL wait

            But how to figure out what is the exact case here?

            Also, needed answer for the earlier question:

            How to find which is the Resource involved in the Deadlock?

            • I already checked using the SQL command - select object_name,owner,data_object_id from dba_objects where data_object_id=39341
            • No rows are returned for this query
            • 3. Re: Re: Deadlock Graph- help required
              Etbin

              Sorry, I'm a rather unprivileged user (a sort of thirteenth pig) when DBA privileges must be dealt with and having no access to system views I have no idea how a java client might manage locks or it's just due to Oracle implicit locking as it appears you're dealing with competing sessions executing the same query simultaneously.

              Inserting into DeviceDetails might imply some DeviceMaster exists but I'm not able to find anything useful about locking related to Master/Detail tables at the moment.

              Maybe a look at https://asktom.oracle.com/pls/apex/f?p=100:11:0::::P11_QUESTION_ID:2106879111815 to find out how to identify locks.

              Once the possibility of deadlocks is identified, I usally try to reproduce the situation manually (in essence the same way Tom demonstrates) retaining the explicit locking once everything about how to avoid deadlocks is clear and understood - no need to bother DBAs to provide results of querying system views I don't have access to.


              Regards


              Etbin

              • 5. Re: Deadlock Graph- help required
                Jonathan Lewis

                When TX/4 locks are part of the deadlock graph you can't depend on the rowid information to be correct, it may simply be the residue from an earlier wait - but you could always dump the block to see what it now holds. (The fact that both sessions report the same block suggests that it might be a space management block, but the numbers need not be about blocks at all.)

                 

                Depending on your version of Oracle you might find the session wait history in the trace file - which would tell you if you had had an ITL wait.

                The most common cause of TX/4, though is index related, with several possible causes e.g.

                     two sessions inserting the same pair of unique rows in the opposite order

                     two sessions trying to insert child rows for a parent that the other session has deleted but not committed.

                 

                The first example is the commonest issue, but you can't tell from the trace file is that is what actually happened. You can only walk the logic of the code to work out if that could happen, or get the code to report the values it was trying to insert when the deadlock happened.

                 

                Regards

                Jonathan Lewis

                1 person found this helpful
                • 6. Re: Deadlock Graph- help required
                  VivekSree

                  Here is the Session History as per the trace file, would this confirm the problem:

                  Sampled Session History of session 486 serial 6421

                  sample interval: 1 sec, max history 120 sec

                      ---------------------------------------------------

                        [3 samples,                                          23:03:30 - 23:03:32]

                          waited for 'enq: TX - row lock contention', seq_num: 41278

                            p1: 'name|mode'=0x54580004

                            p2: 'usn<<16 | slot'=0x20005

                            p3: 'sequence'=0x131f6

                            time_waited: >= 2 sec (still in wait)

                        [1 sample,                                                      23:03:29]

                          idle wait at each sample

                        [1 sample,                                                      23:03:28]

                          waited for 'cursor: pin S wait on X', seq_num: 41111

                            p1: 'idn'=0x54068ff1

                            p2: 'value'=0x2db00000000

                            p3: 'where'=0x500000000

                            time_waited: 0.009921 sec (sample interval: 0 sec)

                        [1 sample,                                                      23:03:27]

                          waited for 'db file sequential read', seq_num: 40933

                            p1: 'file#'=0xa

                            p2: 'block#'=0x16da

                            p3: 'blocks'=0x1

                            time_waited: 0.008119 sec (sample interval: 0 sec)

                        [1 sample,                                                      23:03:26]

                          waited for 'cursor: pin S wait on X', seq_num: 40808

                            p1: 'idn'=0x2c8b0de

                            p2: 'value'=0x2db00000000

                            p3: 'where'=0x500000000

                            time_waited: 0.117484 sec (sample interval: 0 sec)

                        [85 samples,                                         23:02:01 - 23:03:25]

                          idle wait at each sample

                        [1 sample,                                                      23:02:00]

                          waited for 'log file sync', seq_num: 38889

                            p1: 'buffer#'=0x3686

                            p2: 'sync scn'=0x3cea220

                            p3: ''=0x0

                            time_waited: 0.056817 sec (sample interval: 0 sec)

                        [28 samples,                                         23:01:32 - 23:01:59]

                          idle wait at each sample

                   

                     There are 1 sessions blocked by this session.

                      Dumping one waiter:

                        inst: 1, sid: 731, ser: 1603

                        wait event: 'enq: TX - row lock contention'

                          p1: 'name|mode'=0x54580004

                          p2: 'usn<<16 | slot'=0x7001f

                          p3: 'sequence'=0x131c5

                        row_wait_obj#: 39341, block#: 10283, row#: 0, file# 10

                        min_blocked_time: 0 secs, waiter_cache_ver: 18433

                      Wait State:

                        fixed_waits=0 flags=0x22 boundary=(nil)/-1

                      Session Wait History:

                          elapsed time of 0.000191 sec since current wait

                       0: waited for 'SQL*Net message from client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41274 seq_num=41277 snap_id=1

                          wait times: snap=0.003935 sec, exc=0.003935 sec, total=0.003935 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000092 sec of elapsed time

                       1: waited for 'SQL*Net message to client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41273 seq_num=41276 snap_id=1

                          wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000097 sec of elapsed time

                       2: waited for 'SQL*Net message from client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41272 seq_num=41275 snap_id=1

                          wait times: snap=0.010857 sec, exc=0.010857 sec, total=0.010857 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000138 sec of elapsed time

                       3: waited for 'SQL*Net message to client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41271 seq_num=41274 snap_id=1

                          wait times: snap=0.000000 sec, exc=0.000000 sec, total=0.000000 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000087 sec of elapsed time

                       4: waited for 'SQL*Net message from client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41270 seq_num=41273 snap_id=1

                          wait times: snap=0.000315 sec, exc=0.000315 sec, total=0.000315 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000005 sec of elapsed time

                       5: waited for 'SQL*Net message to client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41269 seq_num=41272 snap_id=1

                          wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000124 sec of elapsed time

                       6: waited for 'SQL*Net message from client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41268 seq_num=41271 snap_id=1

                          wait times: snap=0.000158 sec, exc=0.000158 sec, total=0.000158 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000005 sec of elapsed time

                       7: waited for 'SQL*Net message to client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41267 seq_num=41270 snap_id=1

                          wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000188 sec of elapsed time

                       8: waited for 'SQL*Net message from client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41266 seq_num=41269 snap_id=1

                          wait times: snap=0.002965 sec, exc=0.002965 sec, total=0.002965 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000078 sec of elapsed time

                       9: waited for 'SQL*Net message to client'

                          driver id=0x54435000, #bytes=0x1, =0x0

                          wait_id=41265 seq_num=41268 snap_id=1

                          wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec

                          wait times: max=infinite

                          wait counts: calls=0 os=0

                          occurred after 0.000094 sec of elapsed time

                  1 person found this helpful
                  • 7. Re: Deadlock Graph- help required
                    Jonathan Lewis

                    Picking out the two most relevant bits:

                     

                    Sampled Session History of session 486 serial 6421

                    sample interval: 1 sec, max history 120 sec

                        ---------------------------------------------------

                          [3 samples,                                          23:03:30 - 23:03:32]

                            waited for 'enq: TX - row lock contention', seq_num: 41278

                              p1: 'name|mode'=0x54580004

                     

                     

                       There are 1 sessions blocked by this session.

                        Dumping one waiter:

                          inst: 1, sid: 731, ser: 1603

                          wait event: 'enq: TX - row lock contention'

                            p1: 'name|mode'=0x54580004

                     

                    The p1 decodes to TX mode 4

                    The wait is "enq: TX - row lock contention" - it's related to uniqueness (or referential integrity)

                    If it were ITL waits the wait would be "enq: TX - allocate ITL entry".

                     

                    Regards

                    Jonathan Lewis