Rollback to Savepoint Does Not Release Locks

I read that rolling back to a savepoint releases locks. This sounded reasonable so I decided to check it out in an Oracle 11.2 database. I logged in as user John (in blue) and noted my SID for future reference. Then I created a table, inserted a row, committed the change and created a savepoint. Finally I updated the row but did not commit the change, thus setting up a lock:

 

SQL> conn john/smith

Connected.

SQL> select distinct sid from v$mystat

  2  /

 

       SID

----------

       683

 

SQL> create table tab1

  2  (col1 number)

  3  /

 

Table created.

 

SQL> insert into tab1 values(1)

  2  /

 

1 row created.

 

SQL> commit

  2  /

 

Commit complete.

 

SQL> select * from tab1

  2  /

 

      COL1

----------

         1

 

SQL> savepoint sp1

  2  /

 

Savepoint created.

 

SQL> update tab1 set col1 = 2

  2  /

 

1 row updated.

 

SQL> select * from tab1

  2  /

 

      COL1

----------

         2

 

SQL>

 

I logged into a new session as user Fred (in red), noted my SID again and tried to update the same table. This did nothing, as you might expect:

 

SQL> conn fred/bloggs

Connected.

SQL> select distinct sid from v$mystat

  2  /

 

       SID

----------

         5

 

SQL> update john.tab1 set col1 = 3

  2  /

 

I returned to John’s session and checked that I could see the lock in the DBA_WAITERS view. Then I rolled back to the savepoint and checked that the original value had reappeared in the table (it had). However, the lock was still shown in DBA_WAITERS:

 

SQL> show user

USER is "JOHN"

SQL> select holding_session, waiting_session

  2  from dba_waiters

  3  /

 

HOLDING_SESSION WAITING_SESSION

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

            683               5

 

SQL> rollback to savepoint sp1

  2  /

 

Rollback complete.

 

SQL> select * from tab1

  2  /

 

      COL1

----------

         1

 

SQL> select holding_session, waiting_session

  2  from dba_waiters

  3  /

 

HOLDING_SESSION WAITING_SESSION

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

            683               5

 

SQL>

 

I guessed that Oracle must still be holding some kind of lock between the two transactions. There was clearly no lock on the data any more as Donald was able to start a new session (in green) and update it with no problems:

 

SQL> conn donald/duck

Connected.

SQL> update john.tab1 set col1 = 4

  2  /

 

1 row updated.

 

SQL> select * from john.tab1

  2  /

 

      COL1

----------

         4

 

SQL> commit

  2  /

 

Commit complete.

 

SQL>

 

User John finished his transaction and the lock disappeared:

 

SQL> show user

USER is "JOHN"

SQL> commit

  2  /

 

Commit complete.

 

SQL> select holding_session, waiting_session

  2  from dba_waiters

  3  /

 

no rows selected

 

SQL>

 

… and this allowed Fred’s earlier update to finish:

 

SQL> conn fred/bloggs

Connected.

SQL> select distinct sid from v$mystat

  2  /

 

       SID

----------

         5

 

SQL> update john.tab1 set col1 = 3

  2  /

 

1 row updated.

 

SQL>

DBMS_MONITOR.SESSION_TRACE_ENABLE

This happened on Oracle 11.2. I had a problem with a 3^rd party application hosted in the UK with users in another country. The front-end application was failing regularly with ORA-01426. I needed to know which SQL was causing these errors. First I logged into a test database as user ORACLE:

 

SQL> show user

USER is "ORACLE"

SQL>

 

Then I started a trace of this session as follows:

 

SQL> show user

USER is "SYS"

SQL> select sid, serial# from v$session

  2  where username = 'ORACLE'

  3  /

 

       SID    SERIAL#

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

       102       1354

 

SQL> exec dbms_monitor.session_trace_enable(102,1354);

 

PL/SQL procedure successfully completed.

 

SQL>

 

I ran some SQL to produce an ORA-01426 in the traced session:

 

SQL> show user

USER is "ORACLE"

SQL> select power(70,70) from dual

  2  /

select power(70,70) from dual

       *

ERROR at line 1:

ORA-01426: numeric overflow

 

SQL>

 

Then I stopped the trace:

 

SQL> show user

USER is "SYS"

SQL> exec dbms_monitor.session_trace_disable(102,1354);

 

PL/SQL procedure successfully completed.

 

SQL>

 

… but when I looked for the statement in the trace file, I could see no mention of the ORA-01426:

 

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

PARSING IN CURSOR #2 len=29 dep=0 uid=8354 oct=3 lid=8354 tim=31182397151149 hv=1978710958 ad='397d685b0' sqlid='0c4sm5duz1fxf'

select power(70,70) from dual

END OF STMT

PARSE #2:c=0,e=217,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=31182397151146

EXEC #2:c=0,e=403,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=31182397532682

WAIT #2: nam='SQL*Net message to client' ela= 12 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=31182397532829

FETCH #2:c=0,e=199,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1546270724,tim=31182397533145

STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'

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

 

I had hoped that I would be able to trace the application, search the trace file(s) for the ORA-01426 and thus identify the failing SQL but it looks as if I will need to try something else. More to follow…

ORA-00028

This example shows how to kill a user session. You can view sessions in your database as follows:

SQL> col username format a10
SQL> l
  1  select username, sid, serial#, status
  2  from v$session
  3* where username = 'ANDREW'
SQL> /

USERNAME          SID    SERIAL# STATUS
---------- ---------- ---------- --------
ANDREW            143         79 INACTIVE

SQL>

You can then use the SID and SERIAL# displayed to kill a session as shown below. The username you are interested in may have more than one session. If this happens, you will need to use one or more of the other columns in V$SESSION (e.g.OSUSER, MACHINE, LOGON_TIME etc) to see exactly which session you want to get rid of:

SQL> alter system kill session '143,79';
 

System altered.
 

SQL>

The killed session stays in V$SESSION with a status of KILLED:

SQL> select username, sid, serial#, status
  2  from v$session
  3  where username = 'ANDREW';

USERNAME          SID    SERIAL# STATUS
---------- ---------- ---------- --------
ANDREW            143         79 KILLED

SQL>

Until the user tries to access it again (the connection was made earlier). He will then get an ORA-00028:

SQL> conn andrew/reid@test10
Connected.
SQL> select sysdate from dual;
select sysdate from dual
*
ERROR at line 1:
ORA-00028: your session has been killed

SQL>

... and the session will disappear from V$SESSION:

SQL> select username, sid, serial#, status
  2  from v$session
  3  where username = 'ANDREW';

no rows selected

SQL>

ORA-00030

This was tested on Oracle 11.2. When you run ALTER SYSTEM KILL SESSION ‘X,Y’; X must be a SID from V$SESSION and Y must be the SERIAL# from the same row. If not, you will get an ORA-00030: 

SQL> select count(*) from v$session

  2  where sid = 123

  3  and serial# = 321

  4  /

 

  COUNT(*)

----------

         0

 

SQL> alter system kill session '123,321'

  2  /

alter system kill session '123,321'

*

ERROR at line 1:

ORA-00030: User session ID does not exist.

 

SQL>

ORA-00026

This was tested on Oracle 9. When you use the ALTER SYSTEM KILL SESSION command, you must supply the SID and SERIAL# from an entry in V$SESSION. You get an ORA-00026 if you do not provide one: 

SQL> alter system kill session

  2  /

alter system kill session

                        *

ERROR at line 1:

ORA-00026: missing or invalid session ID

 

SQL>

 

The SID and SERIAL# are both numbers so you also get an ORA-00026 if you give non numeric values:

 

SQL> alter system kill session 'A,B'

  2  /

alter system kill session 'A,B'

*

ERROR at line 1:

ORA-00026: missing or invalid session ID

 

SQL>

 

… or values which do not come from V$SESSION:

 

SQL> select count(*) from v$session

  2  where sid = 123

  3  and serial# = 456

  4  /

 

  COUNT(*)

----------

         0

 

SQL> alter system kill session '123,456'

  2  /

alter system kill session '123,456'

*

ERROR at line 1:

ORA-00026: missing or invalid session ID

 

SQL>

 

However, if the values are valid, the command should work:

 

SQL> select sid, serial# from v$session

  2  where username = 'ANDREW'

  3  /

 

       SID    SERIAL#

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

        13         34

 

SQL> alter system kill session '13,34'

  2  /

 

System altered.

 

SQL>

Granting Access to Your Details in V$SESSION

You can allow a user to see details of his own session in V$SESSION like this. First do the following as SYS:

SQL> conn / as sysdba

Connected.

SQL> create view session_log as

  2  select * from v$session

  3  where username = user;

View created.

SQL> create public synonym session_log

  2  for session_log;

Synonym created.

SQL> grant select on session_log to public;

Grant succeeded.

SQL>

Now, still as SYS, create a user to test this out: 

SQL> grant create session

  2  to andrew identified by reid;

 

Grant succeeded.

SQL>

Connect as the user, show that you can only see 1 row in session_log and note its SID and SERIAL#:

 

SQL> conn andrew/reid

Connected.

SQL> select sid, serial# from session_log;

 

       SID    SERIAL#

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

       589        141

 

SQL>

Leave that session logged in to SQL*Plus and reconnect as SYS. Confirm that the SID and SERIAL# for Andrew's session match those shown above:

SQL> conn / as sysdba

Connected.

SQL> select sid, serial# from v$session

  2  where username = 'ANDREW';

       SID    SERIAL#

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

       589        141

SQL>

Excessive CPU Usage in Oracle 11.2.0.1.0

I had a problem with excessive CPU usage in Oracle 11.2.0.1.0. One piece of SQL in particular, which runs quickly on other versions, was taking up to 30 seconds to finish. While it was running, two waits could be seen in the database:

SQL> l

  1  select sid, event, seconds_in_wait

  2  from v$session_wait

  3  where wait_class <> 'Idle'

  4* order by sid, event

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 SQL*Net more data from client                7

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 asynch descriptor resize                     3

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 asynch descriptor resize                     7

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 asynch descriptor resize                    10

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   156 SQL*Net message to client                    0

 

SQL>

 

At this stage, I was not concerned with the SQL*Net more data from client event, just the asynch descriptor resize event. I looked on My Oracle Support and decided it could be caused by bug 9829397. Oracle has various patches available to fix the problem. The workaround is to set disk_asynch_io to false.

 

According to Oracle:

 

DISK_ASYNCH_IO controls whether I/O to datafiles, control files, and logfiles is asynchronous (that is, whether parallel server processes can overlap I/O requests with CPU processing during table scans). If your platform supports asynchronous I/O to disk, Oracle recommends that you leave this parameter set to its default value. However, if the asynchronous I/O implementation is not stable, you can set this parameter to false to disable asynchronous I/O. If your platform does not support asynchronous I/O to disk, this parameter has no effect.

 

First I checked that it was set to true:

 

SQL> l

  1  select value from v$parameter

  2* where name = 'disk_asynch_io'

SQL> /

 

VALUE

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

TRUE

 

SQL>

 

Then I set it to false to check if this was causing my problem (I had to bounce the database to do so):

 

SQL> l

  1  select value from v$parameter

  2* where name = 'disk_asynch_io'

SQL> /

 

VALUE

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

FALSE

 

SQL>

 

Then I read elsewhere in the Oracle documentation that:

 

If you set DISK_ASYNCH_IO to false, then you should also set DBWR_IO_SLAVES to a value other than its default of zero in order to simulate asynchronous I/O.

 

So I set it to 1 (I had to bounce the database to do this):

 

SQL> l

  1  select value from v$parameter

  2* where name = 'dbwr_io_slaves'

SQL> /

 

VALUE

----------

1

 

SQL>

 

After this, the performance was much better and the worst performing piece of SQL took an average of 3 seconds to run instead of 30. This showed that I had identified the problem correctly. However, as a long term solution it might be better to move to a version of Oracle which is not affected by this problem at all.

Hit Ratio by Session

This was tested on Oracle 11.2. I recently did a post showing how you could calculate your database's hit ratio. If you need to see the hit ratio broken down by session, you can do it like this:

SQL> select a.sid, trunc

  2  ((1-(physical_reads/(db_block_gets+consistent_gets)))*100,1)||'%'

  3  hit_ratio from

  4  (select sid, ses.value physical_reads

  5   from v$sesstat ses, v$sysstat sys

  6   where ses.statistic# = sys.statistic#

  7   and name = 'physical reads') a,

  8  (select sid, ses.value db_block_gets

  9   from v$sesstat ses, v$sysstat sys

 10   where ses.statistic# = sys.statistic#

 11   and name = 'db block gets') b,

 12  (select sid, ses.value consistent_gets

 13   from v$sesstat ses, v$sysstat sys

 14   where ses.statistic# = sys.statistic#

 15   and name = 'consistent gets') c

 16  where a.sid = b.sid

 17    and b.sid = c.sid

 18    and db_block_gets + consistent_gets <> 0

 19  order by sid

 20  /

       SID HIT_RATIO

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

         2 99.6%

         4 99.9%

         5 99.6%

         6 99.7%

        25 99.5%

        47 100%

        50 99.9%

        51 99.6%

        67 99.5%

        70 100%

        71 100%

        91 98.3%

        92 99.9%

        93 99.4%

       112 95.6%

       113 98.8%

       115 99.3%

       116 99.5%

       133 94.4%

       134 97.7%

       137 98.6%

       139 100%

       140 99.7%

       156 99.2%

       159 99.8%

       160 99.1%

26 rows selected.

SQL>

db file scattered read

I tested this example on Oracle 11.2.

I wanted to see whether the TIME_WAITED column in V$SESSION_EVENT is only incremented for events such as db file scattered read and db file sequential read if Oracle has to go to disk to satisfy a read request. I decided to check this out using the db file scattered read event, which is associated with full table scans. Before I started, I created a table called ANDREWS_TABLE. Then I checked the total time my session had waited for the event in question:

SQL> select time_waited

  2  from v$session_event

  3  where sid = (select distinct sid from v$mystat)

  4  and event = 'db file scattered read'

  5  /

TIME_WAITED

-----------

        520

SQL>

Next I counted the rows in the table. This was the first time I had done this so Oracle had to get the rows from disk:

SQL> set timing on

SQL> select count(*) from andrews_table

  2  /

  COUNT(*)

----------

     12308

Elapsed: 00:00:00.18

SQL> set timing off

SQL>

I checked the total time waited for the event and it had increased by 0.15 seconds – so far so good:

SQL> select time_waited

  2  from v$session_event

  3  where sid = (select distinct sid from v$mystat)

  4  and event = 'db file scattered read'

  5  /

TIME_WAITED

-----------

        535

SQL>

I counted the rows again. This time Oracle already had the blocks in memory so it did not have to go to disk:

SQL> set timing on

SQL> select count(*) from andrews_table

  2  /

  COUNT(*)

----------

     12308

Elapsed: 00:00:00.01

SQL> set timing off

SQL>

The elapsed time went down from 0.18 seconds to 0.01 seconds because Oracle already had the rows in memory. Finally I checked the time waited for the event again:

SQL> select time_waited

  2  from v$session_event

  3  where sid = (select distinct sid from v$mystat)

  4  and event = 'db file scattered read'

  5  /

TIME_WAITED

-----------

        535

SQL>

It had not increased, showing that the TIME_WAITED for this event only goes up during a full table scan if Oracle has to fetch blocks from disk.