Skip to Main Content
  • Questions

  • Same query from multipule sessions, but dont see Read By Multipule Session

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Sandeep.

Asked: August 01, 2017 - 4:13 pm UTC

Last updated: August 16, 2017 - 1:03 pm UTC

Version: 11.2.0.4.0

Viewed 1000+ times

You Asked

Hi,

I was going through the below link, and doing some testing of my own.

http://oracleinaction.com/simulate-buff-busy/

Focusing only on the below.

PROCEDURE RUNSELECT
as
cursor dummy is select * from t;
c1 t_refcur;
rec dummy%rowtype;
begin
for i in 1..1000000
loop
c1:=retDSQL(‘select * from t’);
loop
fetch c1 into rec;
exit when c1%notfound;
end loop;
close c1;
end loop;

end RUNSELECT;

I ran the above procedure from 5 different sessions, at the same time.

From another session I ran the below query.

select username,sid,serial#,sql_id,event,p1 file#,p2 block#
from v$session
where sid in
(select sid from v$session
where username='TEST');

and I see the below out put

89km4qj1thh13
select * from t

9cnaxppp75nxq
BEGIN GEN_BUF_BUSY.runSELECT; END;

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 9cnaxppp75nxq db file scattered read 4 553
TEST 45 29 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 48 37 9cnaxppp75nxq SQL*Net message from client 1650815232 1
TEST 54 89 89km4qj1thh13 cursor: pin S 1134051363 2.0616E+11
TEST 57 83 9cnaxppp75nxq SQL*Net message from client 1650815232 1

SQL> /

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 89km4qj1thh13 db file scattered read 4 553
TEST 45 29 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 48 37 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 54 89 89km4qj1thh13 cursor: pin S 1134051363 2.0616E+11
TEST 57 83 89km4qj1thh13 SQL*Net message from client 1650815232 1

SQL> /

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 89km4qj1thh13 db file scattered read 4 553
TEST 45 29 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 48 37 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 54 89 89km4qj1thh13 cursor: pin S 1134051363 2.0616E+11
TEST 57 83 89km4qj1thh13 SQL*Net message from client 1650815232 1

SQL> /

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 9cnaxppp75nxq db file scattered read 4 553
TEST 45 29 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 48 37 9cnaxppp75nxq SQL*Net message from client 1650815232 1
TEST 54 89 89km4qj1thh13 cursor: pin S 1134051363 2.0616E+11
TEST 57 83 89km4qj1thh13 SQL*Net message from client 1650815232 1

SQL> /

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 9cnaxppp75nxq db file scattered read 4 553
TEST 45 29 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 48 37 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 54 89 9cnaxppp75nxq cursor: pin S 1134051363 2.0616E+11
TEST 57 83 9cnaxppp75nxq SQL*Net message from client 1650815232 1

SQL> /

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 9cnaxppp75nxq db file scattered read 4 553
TEST 45 29 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 48 37 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 54 89 9cnaxppp75nxq cursor: pin S 1134051363 2.0616E+11
TEST 57 83 89km4qj1thh13 SQL*Net message from client 1650815232 1

SQL> /

USERNAME SID SERIAL# SQL_ID EVENT FILE# BLOCK#
------------------------------ ---------- ---------- ------------- ------------------------------ ---------- ----------
TEST 44 21 89km4qj1thh13 db file scattered read 4 553
TEST 45 29 9cnaxppp75nxq SQL*Net message from client 1650815232 1
TEST 48 37 89km4qj1thh13 SQL*Net message from client 1650815232 1
TEST 54 89 89km4qj1thh13 cursor: pin S 1134051363 2.0616E+11
TEST 57 83 89km4qj1thh13 SQL*Net message from client 1650815232 1

Could you please help explaining the above pattern?
And why I am not seeing "Read by other session" here ?

Regards,
Sandeep

and Connor said...

I didnt look too closely at the code, but things get better with each release of Oracle as we improve the concurrency management of blocks in the cache.

A far simpler way of looking at busy buffers is to have two sessions compete for index blocks, eg

SQL> create table t as select 1 x, 'y' y from dual;

Table created.

SQL> create index ix on t ( x ) ;

Index created.

--
-- 'n' sessions do this
--
SQL> begin
  2  for i in 1 .. 100000 loop
  3    insert into t values (1,'z');
  4  end loop;
  5  end;
  6  /

PL/SQL procedure successfully completed.

--
-- and here's the session waits from one of those sessions
--
SQL> @sessev
Sid (Default=this session):

EVENT                                        TOTAL_WAITS TOTAL_TIMEOUTS       SECS
-------------------------------------------- ----------- -------------- ----------
Disk file operations I/O                               2              0        .01
enq: TX - index contention                            59              0        .01
events in waitclass Other                             54              4        .03
buffer busy waits                                   1801              0        .03


Rating

  (6 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Sandeep, August 02, 2017 - 5:23 am UTC

Hi Connor,

Thank you.

This time I was not trying to simulate, "buffer busy wait".
But thank you again, for the beautiful explanation.

I am trying to simulate "ORA-04031: unable to allocate 4032 bytes of shared memory"

The Idea is to run
"select * from t"
tens of thousands of times from multiple sessions.
Since no bind variables are used, and it is a * query
so each time it will be doing hard parsing and soon the shared pool should run out of space.

So I have burrowed the piece of code which does the select, from the link I have given, in the question.

The output which I have given in the question, shows that only one session is doing the table scan, and rest of the others are simply idle.

As per my understanding rest of the session should be waiting not on "SQL* Net message from client", rather they should be waiting on "Read by other session" and had it been earlier to 10g it should show "Buffer busy".

The second question is why I still not see the ORA-04031 ?

Could you please help .

Regards,
Sandeep
Connor McDonald
August 04, 2017 - 1:42 am UTC

"ORA-04031: unable to allocate 4032 bytes of shared memory"

If you are trying to get that, you need to flood the shared pool with lots (thousandas) of cursors all pinned for use. This is unrelated to block buffers in memory.

If you are want to get 'read by other session', similarly that is not about contention for buffers *in* memory, it is about contention for getting buffer *into* memory.

That is, two people read the same block which happens to be on disk.

One of them will be tasked with the effort of reading it off disk into the buffer cache. The other will told to wait until it is there, and can then get it from the cache. Hence they are waiting on a "read.." (from disk into memory) "...by other session"


To Sandeep

J. Laurindo Chiappa, August 02, 2017 - 1:50 pm UTC

Hello, Sandeep : no, you are wrong running one SQL with '*' will NOT imply in hard parses : parsing in the Oracle RDBMS is based by default on the TEXT of the SQL, so if the TEXT is always the same (with * or not) , NO HARD PARSES will occur.. See :

==> Right now I have in my test database :

chiappa@TEST#1:TEST#1-DESENV:SQL>select name, value from v$sysstat where name like 'parse count%';

NAME VALUE
---------------------------------------------------------------- ---------
parse count (total) 1597177
parse count (hard) 107948
parse count (failures) 343

chiappa@TEST#1:TEST#1-DESENV:SQL>


==> I will create a .BAT scripting repeating 1000 times the l.sql script, that will send always the very same SQL text (using SELECT * but matters not) :

C:\Developers>type l.bat
FOR /L %%G IN (1,1,1000) DO sqlplus scott/tiger@wTEST#1 @l.sql

==> The l.bat script , to be repeated 1000 times :

C:\Developers>type l.sql
select * from dept;
exit
/

C:\Developers>

==> executing...

C:\Developers>l.bat

C:\Developers>sqlplus scott/tiger@wTEST#1 @l.sql

SQL*Plus: Release 10.2.0.5.0 - Production on Wed Aug 2 09:59:39 2017

Copyright (c) 1982, 2010, Oracle. All Rights Reserved.


Connected to:
Oracle Database 10g Release 10.2.0.5.0 - 64bit Production


DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON

Disconnected from Oracle Database 10g Release 10.2.0.5.0 - 64bit Production

C:\Developers>sqlplus scott/tiger@wTEST#1 @l.sql

SQL*Plus: Release 10.2.0.5.0 - Production on Wed Aug 2 09:59:39 2017

Copyright (c) 1982, 2010, Oracle. All Rights Reserved.


Connected to:
Oracle Database 10g Release 10.2.0.5.0 - 64bit Production


DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON

Disconnected from Oracle Database 10g Release 10.2.0.5.0 - 64bit Production

C:\Developers>sqlplus scott/tiger@wTEST#1 @l.sql

SQL*Plus: Release 10.2.0.5.0 - Production on Wed Aug 2 09:59:39 2017

Copyright (c) 1982, 2010, Oracle. All Rights Reserved.


Connected to:
Oracle Database 10g Release 10.2.0.5.0 - 64bit Production


DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON

Disconnected from Oracle Database 10g Release 10.2.0.5.0 - 64bit Production

C:\Developers>sqlplus scott/tiger@wTEST#1 @l.sql

SQL*Plus: Release 10.2.0.5.0 - Production on Wed Aug 2 09:59:39 2017

Copyright (c) 1982, 2010, Oracle. All Rights Reserved.


Connected to:
Oracle Database 10g Release 10.2.0.5.0 - 64bit Production


DEPTNO DNAME LOC
---------- -------------- -------------
10 ACCOUNTING NEW YORK
20 RESEARCH DALLAS
30 SALES CHICAGO
40 OPERATIONS BOSTON

Disconnected from Oracle Database 10g Release 10.2.0.5.0 - 64bit Production

....... it will be going on and on, until execute 1000 times... After that , consulting the parse statistics system-level :

chiappa@TEST#1:TEST#1-DESENV:SQL>/

NAME VALUE
---------------------------------------------------------------- ---------
parse count (total) 1611895
parse count (hard) 107981
parse count (failures) 345

chiappa@TEST#1:TEST#1-DESENV:SQL>


===>>> see, we don´t get 1000 hard parses, not even close.... Right ? The thing about HARD PARSING in the absence of bind variables is in this line : suppose an environment where part of the SQL text to be sent to the database is 'glued' dynamically, more or less like :

v_text := 'SELECT * FROM table WHERE nameofkeycolumn = ' || variablecontaingthe value
execute v_text;

With this, if a given session pass the value 32 to the variable, the SQL text sent will be :

SELECT * FROM table WHERE nameofkeycolumn=32

Another session passing the value 45 will send :

SELECT * FROM table WHERE nameofkeycolumn=45

And so on... In THIS scenery you will fill the SQL cache area, right ??? The problem is NOT the use of '*' , BUT the fact that "SELECT * FROM table WHERE nameofkeycolumn=32" is a DIFFERENT TEXT comparing with "SELECT * FROM table WHERE nameofkeycolumn=45".. Got it ? See https://asktom.oracle.com/pls/asktom/f?p=100:11:0::::p11_question_id:528893984337 for more ref about it....

Another point : see the SQL executions for my example SQL text : NO childs, NO invalidations...

chiappa@TEST#1:TEST#1-DESENV:SQL>select fetches, executions, rows_processed, parse_calls, open_versions, invalidations, child_number, elapsed_time, cpu_time, kept_versions, exact_matching_signature from v$sql where sql_text = 'select * from dept';

FETCHES EXECUTIONS ROWS_PROCESSED PARSE_CALLS OPEN_VERSIONS INVALIDATIONS CHILD_NUMBER ELAPSED_TIME CPU_TIME KEPT_VERSIONS EXACT_MATCHING_SIGNATURE
---------- ---------- -------------- ----------- ------------- ------------- ------------ ------------ ---------- ------------- ------------------------
2000 1000 4000 1000 0 0 0 137534 78125 0 1.0265E+19


==> And if you are wondering about the 1000 parse calls, see https://asktom.oracle.com/pls/apex/f?p=100:11:0::::P11_QUESTION_ID:2588723819082 to learn that if no hard parses are registered, thus these parse calls were SOFT PARSES....

Speaking for your need to test/simulate "ORA-04031: unable to allocate 4032 bytes of shared memory" due to , you would neeed to use some kind of DYNAMIC SQL, generating for each execution DIFFERENT SQL TEXTS : with this yes, you will have a LOT of different entries in V$SQL and alike ones....
Obvious#2 : of course, to enhance your chances in the sense of receiving ORA-4031, turn OFF automatic memory management AND have a SMALL shared pool...

Regards,

J. Laurindo Chiappa
Connor McDonald
August 03, 2017 - 1:00 am UTC

nice input

To Chiappa

Sandeep, August 03, 2017 - 2:50 am UTC

Hi Chiappa,

Superb, Many Many Thanks.
By myself I went till querying v$sql and was getting the number of executions and parses, but was not sure whether they were hard or soft. thanks to you, now it is clear.

The only question now remains is;
In my version of test scenario ( the Title of the question ) I see only one session is doing "db file scattered read", and rest are "SQL * net from client". I suppose I should rather see read by other session ?

Could you please help?

Regards,
Sandeep

To Sandeep

J. Laurindo Chiappa, August 03, 2017 - 11:52 pm UTC

Hi, I'm glad to hear you've learned something new... About the wait, afaik if the block is not being changed (only intensively accessed) iirc you will NOT see the 'buffer busy' wait, BUT a wait for the latch that protects that block... My example :

SYS:AS SYSDBA@orcl:SQL>select employee_id, dbms_rowid.rowid_block_number(rowid) block#, rowid from hr.employees;

EMPLOYEE_ID BLOCK# ROWID
----------- ---------- ------------------
100 245 AAAXPXAAEAAAAD1AAA
101 245 AAAXPXAAEAAAAD1AAB
102 245 AAAXPXAAEAAAAD1AAC
103 245 AAAXPXAAEAAAAD1AAD
104 245 AAAXPXAAEAAAAD1AAE
105 245 AAAXPXAAEAAAAD1AAF
106 245 AAAXPXAAEAAAAD1AAG
107 245 AAAXPXAAEAAAAD1AAH
108 245 AAAXPXAAEAAAAD1AAI
109 245 AAAXPXAAEAAAAD1AAJ
110 245 AAAXPXAAEAAAAD1AAK
111 245 AAAXPXAAEAAAAD1AAL
112 245 AAAXPXAAEAAAAD1AAM
113 245 AAAXPXAAEAAAAD1AAN
114 245 AAAXPXAAEAAAAD1AAO
115 245 AAAXPXAAEAAAAD1AAP
116 245 AAAXPXAAEAAAAD1AAQ
117 245 AAAXPXAAEAAAAD1AAR
118 245 AAAXPXAAEAAAAD1AAS
119 245 AAAXPXAAEAAAAD1AAT
120 245 AAAXPXAAEAAAAD1AAU
121 245 AAAXPXAAEAAAAD1AAV
122 245 AAAXPXAAEAAAAD1AAW
123 245 AAAXPXAAEAAAAD1AAX
124 245 AAAXPXAAEAAAAD1AAY
125 245 AAAXPXAAEAAAAD1AAZ
126 245 AAAXPXAAEAAAAD1AAa
127 245 AAAXPXAAEAAAAD1AAb
128 245 AAAXPXAAEAAAAD1AAc
129 245 AAAXPXAAEAAAAD1AAd
130 245 AAAXPXAAEAAAAD1AAe
131 245 AAAXPXAAEAAAAD1AAf
132 245 AAAXPXAAEAAAAD1AAg
133 245 AAAXPXAAEAAAAD1AAh
134 245 AAAXPXAAEAAAAD1AAi
135 245 AAAXPXAAEAAAAD1AAj
136 245 AAAXPXAAEAAAAD1AAk
137 245 AAAXPXAAEAAAAD1AAl
138 245 AAAXPXAAEAAAAD1AAm
139 245 AAAXPXAAEAAAAD1AAn
140 245 AAAXPXAAEAAAAD1AAo
141 245 AAAXPXAAEAAAAD1AAp
142 245 AAAXPXAAEAAAAD1AAq
143 245 AAAXPXAAEAAAAD1AAr
144 245 AAAXPXAAEAAAAD1AAs
145 245 AAAXPXAAEAAAAD1AAt
146 245 AAAXPXAAEAAAAD1AAu
147 245 AAAXPXAAEAAAAD1AAv
148 245 AAAXPXAAEAAAAD1AAw
149 245 AAAXPXAAEAAAAD1AAx
150 245 AAAXPXAAEAAAAD1AAy
151 245 AAAXPXAAEAAAAD1AAz
152 245 AAAXPXAAEAAAAD1AA0
153 245 AAAXPXAAEAAAAD1AA1
154 245 AAAXPXAAEAAAAD1AA2
155 245 AAAXPXAAEAAAAD1AA3
156 245 AAAXPXAAEAAAAD1AA4
157 245 AAAXPXAAEAAAAD1AA5
158 245 AAAXPXAAEAAAAD1AA6
159 245 AAAXPXAAEAAAAD1AA7
160 245 AAAXPXAAEAAAAD1AA8
161 245 AAAXPXAAEAAAAD1AA9
162 245 AAAXPXAAEAAAAD1AA+
163 245 AAAXPXAAEAAAAD1AA/
164 245 AAAXPXAAEAAAAD1ABA
165 245 AAAXPXAAEAAAAD1ABB
166 245 AAAXPXAAEAAAAD1ABC
167 245 AAAXPXAAEAAAAD1ABD
168 245 AAAXPXAAEAAAAD1ABE
169 245 AAAXPXAAEAAAAD1ABF
170 245 AAAXPXAAEAAAAD1ABG
171 245 AAAXPXAAEAAAAD1ABH
172 245 AAAXPXAAEAAAAD1ABI
173 245 AAAXPXAAEAAAAD1ABJ
174 245 AAAXPXAAEAAAAD1ABK
175 245 AAAXPXAAEAAAAD1ABL
176 245 AAAXPXAAEAAAAD1ABM
177 245 AAAXPXAAEAAAAD1ABN
178 245 AAAXPXAAEAAAAD1ABO
179 245 AAAXPXAAEAAAAD1ABP
180 245 AAAXPXAAEAAAAD1ABQ
181 245 AAAXPXAAEAAAAD1ABR
182 245 AAAXPXAAEAAAAD1ABS
183 245 AAAXPXAAEAAAAD1ABT
184 245 AAAXPXAAEAAAAD1ABU
185 245 AAAXPXAAEAAAAD1ABV
186 245 AAAXPXAAEAAAAD1ABW
187 245 AAAXPXAAEAAAAD1ABX
188 245 AAAXPXAAEAAAAD1ABY
189 245 AAAXPXAAEAAAAD1ABZ
190 245 AAAXPXAAEAAAAD1ABa
191 245 AAAXPXAAEAAAAD1ABb
192 245 AAAXPXAAEAAAAD1ABc
193 245 AAAXPXAAEAAAAD1ABd
194 245 AAAXPXAAEAAAAD1ABe
195 245 AAAXPXAAEAAAAD1ABf
196 245 AAAXPXAAEAAAAD1ABg
197 245 AAAXPXAAEAAAAD1ABh
198 246 AAAXPXAAEAAAAD2AAA
199 246 AAAXPXAAEAAAAD2AAB
200 246 AAAXPXAAEAAAAD2AAC
201 246 AAAXPXAAEAAAAD2AAD
202 246 AAAXPXAAEAAAAD2AAE
203 246 AAAXPXAAEAAAAD2AAF
204 246 AAAXPXAAEAAAAD2AAG
205 246 AAAXPXAAEAAAAD2AAH
206 246 AAAXPXAAEAAAAD2AAI

107 rows selected.

==> Let´s create some SQL accessing the same block always (block#245 in my case) :

SYS:AS SYSDBA@orcl:SQL>create or replace PROCEDURE HR.RUNSELECT as
cursor c is select * from EMPLOYEES where employee_id between 100 and 197;
r c%ROWTYPE;
begin
for i in 1..10000 loop
dbms_application_info.set_client_info('Loop exec#' || i);
open c;
loop
fetch c into r;
exit when c%notfound;
end loop;
close c;
end loop;
end;
2 3 4 5 6 7 8 9 10 11 12 13 14 15
16 /

Procedure created.

==> all right, I opened 4 sessions connect with HR user :

SYS:AS SYSDBA@orcl:SQL>select sid, serial#, client_info from v$session where username='HR';

SID SERIAL# CLIENT_INFO
------ -------- ----------------------------------------------------------------
17 83
31 69
39 51
61 37

==> Will trace the 4 sessions :

SYS:AS SYSDBA@orcl:SQL>exec dbms_system.set_ev(17, 83, 10046, 12, '');

PL/SQL procedure successfully completed.

SYS:AS SYSDBA@orcl:SQL>exec dbms_system.set_ev(31, 69, 10046, 12, '');

PL/SQL procedure successfully completed.

SYS:AS SYSDBA@orcl:SQL>exec dbms_system.set_ev(39, 51, 10046, 12, '');

PL/SQL procedure successfully completed.

SYS:AS SYSDBA@orcl:SQL>exec dbms_system.set_ev(61, 37, 10046, 12, '');

PL/SQL procedure successfully completed.

SYS:AS SYSDBA@orcl:SQL>

==> Executing the same procedure (that reads records from the same block) simultaneously in the 4 sessions :

HR#1:SQL>exec runselect;


HR#2:SQL>exec runselect;


HR#3:SQL>exec runselect;


HR#4:SQL>exec runselect;

==> after the executions, I disconnect to close the trace files :


PL/SQL procedure successfully completed.

HR#1:SQL>exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@localhost ~]$



PL/SQL procedure successfully completed.

HR#2:SQL>exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@localhost ~]$



PL/SQL procedure successfully completed.

HR#3:SQL>exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@localhost ~]$



PL/SQL procedure successfully completed.

HR#4:SQL>exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@localhost ~]$

==> See the waits registered :

[oracle@localhost trace]$ cat orcl_ora_3953_trace_teste_user_hr.trc | grep -i 'wait'
select regflags, numobjs, objarray, plsqlcallback, changelag, username from SYS.invalidation_registry$ where regid = :1 for update NOWAIT
WAIT #11364656: nam='log file sync' ela= 280 buffer#=9218 sync scn=15571874 p3=0 obj#=-1 tim=1501802543068761
WAIT #11498464: nam='latch: cache buffers chains' ela= 40195 address=969423888 number=155 tries=0 obj#=-1 tim=1501802551516737
WAIT #11498464: nam='latch: cache buffers chains' ela= 101315 address=969423888 number=155 tries=0 obj#=-1 tim=1501802564559264
WAIT #11498464: nam='latch: cache buffers chains' ela= 304866 address=969423888 number=155 tries=0 obj#=-1 tim=1501802566670040


[oracle@localhost trace]$ cat orcl_ora_3955_trace_teste_user_hr.trc | grep -i 'wait'
select regflags, numobjs, objarray, plsqlcallback, changelag, username from SYS.invalidation_registry$ where regid = :1 for update NOWAIT
WAIT #6232368: nam='log file sync' ela= 270 buffer#=9211 sync scn=15571872 p3=0 obj#=-1 tim=1501802541064738
WAIT #6366640: nam='db file sequential read' ela= 24 file#=1 block#=1614 blocks=1 obj#=237 tim=1501802541067407
WAIT #6363784: nam='Disk file operations I/O' ela= 0 FileOperation=2 fileno=4 filetype=2 obj#=95191 tim=1501802541089788
WAIT #6363784: nam='db file sequential read' ela= 0 file#=4 block#=245 blocks=1 obj#=95191 tim=1501802541089788
WAIT #6363784: nam='latch: cache buffers chains' ela= 40059 address=969423888 number=155 tries=0 obj#=95191 tim=1501802552279874
WAIT #6363784: nam='latch: cache buffers chains' ela= 101315 address=969423888 number=155 tries=0 obj#=95191 tim=1501802564559264
WAIT #6363784: nam='latch: cache buffers chains' ela= 102638 address=969423888 number=155 tries=0 obj#=95191 tim=1501802566467812
WAIT #6363784: nam='latch: cache buffers chains' ela= 100365 address=969423888 number=155 tries=0 obj#=95191 tim=1501802582897185

[oracle@localhost trace]$ cat orcl_ora_4065_trace_teste_user_hr.trc | grep -i 'wait'
select regflags, numobjs, objarray, plsqlcallback, changelag, username from SYS.invalidation_registry$ where regid = :1 for update NOWAIT
WAIT #8214832: nam='log file sync' ela= 136 buffer#=9225 sync scn=15571876 p3=0 obj#=-1 tim=1501802545191824
WAIT #15541216: nam='latch: cache buffers chains' ela= 200951 address=969423888 number=155 tries=0 obj#=-1 tim=1501802582997840

[oracle@localhost trace]$ cat orcl_ora_4067_trace_teste_user_hr.trc | grep -i 'wait'
select regflags, numobjs, objarray, plsqlcallback, changelag, username from SYS.invalidation_registry$ where regid = :1 for update NOWAIT
WAIT #7100720: nam='Disk file operations I/O' ela= 25 FileOperation=2 fileno=3 filetype=2 obj#=-1 tim=1501802547798404
WAIT #7100720: nam='log file sync' ela= 139613 buffer#=9232 sync scn=15571878 p3=0 obj#=-1 tim=1501802547939223
WAIT #13722592: nam='latch: cache buffers chains' ela= 141949 address=969423888 number=155 tries=0 obj#=-1 tim=1501802551618721
WAIT #13722592: nam='latch: cache buffers chains' ela= 40047 address=969423888 number=155 tries=0 obj#=-1 tim=1501802552279924
WAIT #13722592: nam='latch: cache buffers chains' ela= 201231 address=969423888 number=155 tries=0 obj#=-1 tim=1501802564659180
WAIT #13722592: nam='latch: cache buffers chains' ela= 102691 address=969423888 number=155 tries=0 obj#=-1 tim=1501802566467865
WAIT #13722592: nam='latch: cache buffers chains' ela= 100333 address=969423888 number=155 tries=0 obj#=-1 tim=1501802582897185
[oracle@localhost trace]$

==>> NO 'buffer busy' waits, right ??? Only waits for the latch protecting my buffer number 155 that reside in the address 969423888.... Let´s wait for Connor´s answer but imho to see buffer busy you will need to CHANGE the buffer block in some way...

Regards,

J. Laurindo Chiappa

To Chiaapa

A reader, August 04, 2017 - 5:17 am UTC

Hi Chiappa,

Thank you, the example is impressive and massive.

If you look at the 1st answer provided by Connor, he already has showed the "buffer busy" scenario.

About competing for acquiring the same latch, that is what your example is showing. (good one).

Questions
------------
1. In my case why the rest of the sessions are idle, event is 'SQL* net message from client' ?
2. A straight question/request, under what circumstances you see a "Read by other session" ???. Don't you think, 3 sessions out of four should be showing this wait event, because the same block is already getting red by one session ?????

Regards,
Sandeep


Connor McDonald
August 05, 2017 - 2:56 am UTC

1) Because they are. If I run 1000 commands (not in PLSQL, ie, in a client), they will do:

- run command
- idle

1000 times. If the command runs in 1ms and you are idle for 5ms, you are *still* idle for 83% of the time

2) You need a "bad" I/O system for this, because if you can read data quickly from disk into the buffer cache, you have to be "lucky" to catch it with another session.

Sandeep, August 15, 2017 - 7:34 am UTC

Hi Connor,

Many Thanks.

So can I please have the liberty to summarize as below.

1] One session is reading data from disk to buffer cache
2] Rest are reading the same data from buffer cache, which are already fetched by the 1st session
3] Sessions other than the 1st one, reading from buffer so, it is quick enough for me to notice, rather appearing idle because with each iteration of the loop the requested action is done and then it goes to idle mode till the next iteration of the loop begins. It is appearing idle to me because it is finishing before I could notice.

Kindly add/correct as you feel.

Thanks and Regards,
Sandeep
Connor McDonald
August 16, 2017 - 1:03 pm UTC

That would be a reasonable inference yes.
more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's latest video and Chris's latest video from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

Administration

Need more information on Administration? Check out the Administrators guide for the Oracle Database