Here is a quick and interesting observation regarding the %logons% statistics. The database version is Oracle 19c and, apparently, it applies to earlier versions as well. The question that I am trying to answer here is this “How does a parallel query execution relate to %logon% statistics?”

Here is a test case.

Let’s check the statistics for the instance:

SQL> select name, value from v$sysstat where name like '%logon%';

NAME					          VALUE
-------------------------------- ----------
logons cumulative				  68368
logons current				      108
user logons cumulative            6762

SQL> 

Now, do nothing but log on to the database:

Connected to:
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0

SQL>

Let’s check the statistics again:

SQL> select name, value from v$sysstat where name like '%logon%';

NAME					          VALUE
-------------------------------- ----------
logons cumulative				  68369
logons current				      109
user logons cumulative            6763

SQL> 

As a result, each of the statistics above gets incremented by one. So far, so good.

Now, from within that brand-new session, let’s execute a parallel query:

SQL> select /*+ parallel(8) */ count(*) from tt1;

  COUNT(*)
----------
     73252

SQL> 

Display the statistics to compare:

SQL> select name, value from v$sysstat where name like '%logon%';

NAME					          VALUE
-------------------------------- ----------
logons cumulative				  68377
logons current				      109
user logons cumulative            6763

SQL> 

As a result, the only statistics that changes is “logons cumulative“. It has grown by exactly the number of allocated parallel slaves: 8. Repetitive execution of the same query with different degrees of parallelism increments only this statistics and it does this by that degree each time.

The “logons current” statistics doesn’t change. This one doesn’t include the slave sessions but the coordinator only. The coordinator sid is the actually the sid of the session that executes the query. Another observation is that “user logons cumulative” statistics does not include slave processes either.

This may come in very handy when troubleshooting a logon storm caused by parallel execution.

The quickest and simplest way of ensuring what has been populated in In-Memory column store (IMCS) is to query the V$IM_SEGMENTS view. Whenever an object is loaded into IMCS, the database will add a record about it into this view. In general, I guess the appearance of the IMCS as such is an attempt of Oracle to transition to NewSQL stack.

According to Oracle documentation the IMCS can be enabled for a tablespace, table (including external and excluding IOT), table partition and materialized view (MV). What is more interesting is that it also mentions when, for example, a table gets populated in IMCS – only when it is fully scanned (and not parallelly). Index access methods that cover table tuples and table tuples populated by rowids never load the tuples in IMCS.

Documentation does not say a word about when a MV gets populated in IMCS. It would be reasonable to assume that since a MV is very much like a heap table, then the table IMCS population rules apply to the former as well i.e. for a MV to get populated in IMCS an explicit nonparallel full scan of it is necessary. This is indeed so. Additionally, implicit population of MV is also possible and this with a little trick only. The table access which causes query rewrite (fully accessing the MV) can also trigger it. All this said, this post is not about something advanced but rather an interesting take-away about IMCS.

The test case is on Oracle 12C. First, let’s create a non-empty table and define a MV on it:

SQL> create table testtable1 as select object_id, object_name from dba_objects;

Table created.

SQL> create materialized view testview1 enable query rewrite as select * from testtable1;

Materialized view created.

SQL>

Let’s now enable IMCS for the view and confirm that the it really gets populated in there when scanned fully:

SQL> alter materialized view testview1 inmemory;

Materialized view altered.

SQL> select count(*) from testview1;

  COUNT(*)
----------
     73306

SQL> select segment_name, populate_status from v$im_segments;

SEGMENT_NAME                        POPULATE_STATUS
----------------------------------- -------------
TESTVIEW1			                 COMPLETED

Now, let’s flush the MV from IMCS but make it eligible for population again. Also, let’s query the table so that the query rewrite kicks in:

SQL> alter materialized view testview1 no inmemory;

Materialized view altered.

SQL> alter materialized view testview1 inmemory;

SQL> select segment_name, populate_status from v$im_segments;

no rows selected.

SQL>

As the result from v$im_segments shows, the MV is not there…yet. Let’s cause a full scan of the MV again:

SQL> select count(*) from testview1;

  COUNT(*)
----------
     73306

SQL> select segment_name, populate_status from v$im_segments;

no rows selected.

SQL>

Subsequent executions of the same query still doesn’t make the MV appear in IMCS, although the little trick will make it to get populated:

SQL> alter table testtable1 inmemory;

Table altered.

SQL> select count(*) from testtable1;

  COUNT(*)
----------
     73305

SQL> select segment_name, populate_status from v$im_segments;

SEGMENT_NAME	                POPULATE_STATUS
------------------------------ -------------
TESTVIEW1		                COMPLETED

SQL>

The query plan now is as follows:

Plan hash value: 3466806115
 
-----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                  | Name      | Rows  | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
-----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                           |           |     1 |     3   (0)| 00:00:01 |        |      |            |
|   1 |  SORT AGGREGATE                            |           |     1 |            |          |        |      |            |
|   2 |   PX COORDINATOR                           |           |       |            |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)                     | :TQ10000  |     1 |            |          |  Q1,00 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE                         |           |     1 |            |          |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR                     |           | 73306 |     3   (0)| 00:00:01 |  Q1,00 | PCWC |            |
|   6 |       MAT_VIEW REWRITE ACCESS INMEMORY FULL| TESTVIEW1 | 73306 |     3   (0)| 00:00:01 |  Q1,00 | PCWP |            |
-----------------------------------------------------------------------------------------------------------------------------

The next time the query will execute the table data will be retrieved from the MV which is now in IMCS (the reason for going parallel is described in the note 2373556.1 which is a bug and has a workaround). The query rewrite can cause MV population in IMCS and for that to happen the base table must have the INMEMORY option enabled.

That’s all for this time. More advanced stuff is coming soon…

The following is a (short and quick) scenario I recently faced when analyzing a parallel query and its response time. This may not apply to earlier versions of Oracle though. The experiments were carried out in 19c.

The ‘weird’ behavior I observed was that V$SQL.EXECUTIONS column didn’t get updated for the query under analysis when executed. The first gotcha is, perhaps, “That must be a bug“. Let’s be more systematic however, and arrive at the root cause gradually.

Here is a test case. First, I am simply executing the query three times and checking the v$sql.

SQL> select sql_id, sql_text, executions, child_number from v$sql where sql_text like '%test1%';

SQL_ID	      SQL_TEXT                              EXECUTIONS CHILD_NUMBER
------------- ---------------------------------     ---------- ------------
4gy00kap2kf3n	select /*+ test1 */ * from table1   3	        0
4gy00kap2kf3n	select /*+ test1 */ * from table1   0	        1

2 rows selected.

SQL> 

The output shows that the database decided to generate another child (CHILD_NUMBER=1) for this statement. However, the primary question here is “Why are there NO executions for the second child?“.

The reason for not sharing that can be found from v$sql_shared_cursor is not of interest, although it may shed some light on the question. Still, let’s take a different strategy without consulting this view.

Two approaches can be taken to move forward with this ‘issue’: a) Try A, try B, try C,… and hope it helps to find out the reason, and perhaps, eventually one of them will and b) Ask the right questions. Before blaming the database for bugs, lets put it aside as the last resort. There must be something about this that at this point not known yet and that may lead to the clue.

The simplest question one can ask here can be something like “Would there by any other statistics that applies to child cursors which has probably been missed out?” This is a separate child and, thus, the entry point should be v$sql. Scanning the column names of the view for ‘%EXEC’% reveals another field: PX_SERVERS_EXECUTIONS. Let’s query this column as well:

SQL> select sql_id, sql_text, executions, px_servers_executions, child_number from v$sql where sql_text like '%test1%';

SQL_ID	      SQL_TEXT						      EXECUTIONS PX_SERVERS_EXECUTIONS CHILD_NUMBER
------------- ---------------------------------- ---------- --------------------- ------------

4gy00kap2kf3n select /*+ test1 */ * from table1  3			 0	                   0
4gy00kap2kf3n select /*+ test1 */ * from table1  0			 12	                   1

2 rows selected.

SQL> 

PX_SERVERS_EXECUTIONS holds the total number of executions by the slaves of a parallel query. This explains why the second cursor executions are not reflected in V$SQL.EXECUTIONS column. For parallel slaves Oracle tracks it in a different column: V$SQL.PX_SERVERS_EXECUTIONS and in this case it has been executed 12 times so far. Since the query does have any parallelism forced by the hint, hence the table-level parallelism must set which is confirmed by dba_tables.degree being equal to 4. The one with CHILD_NUMBER=0 is actually the coordinator. The query executes in parallel:

SQL> select * from dbms_xplan.display_cursor('4gy00kap2kf3n', 0, 'ALLSTATS ALL');

SQL_ID	4gy00kap2kf3n, child number 0
-------------------------------------
select /*+ test1 */ * from table1

Plan hash value: 1574891232
 
--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          | 73216 |  9438K|   110   (0)| 00:00:01 |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 | 73216 |  9438K|   110   (0)| 00:00:01 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          | 73216 |  9438K|   110   (0)| 00:00:01 |  Q1,00 | PCWC |            |
|   4 |     TABLE ACCESS FULL| TABLE1   | 73216 |  9438K|   110   (0)| 00:00:01 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------
 
Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 1 (E - Syntax error (1))
---------------------------------------------------------------------------
   1 -  SEL$1
   E -  test1
Note
-----
   - Degree of Parallelism is 4 because of table property

28 rows selected.

SQL>

Morale: Step-by-step approach is the key regardless of the issue and the DBMS.

Oracle optimizer can sometimes trick you and this post is about a finding that clearly demonstrates that. Putting it shortly, while the execution plan shows that the optimizer is doing “INDEX RANGE SCANE”, in actuality it is going with “INDEX UNIQUE SCAN”. Here is a test-case in Oracle 19c.

First, lets create a table, populate it with data and add index on its column.

SQL> create table table1(id integer);

Table created.

SQL> insert into table1 select object_id from dba_objects;

7433 rows created.

SQL> create index IND on table1(id);

Index created.

Let’s confirm the type of the index just created which will be needed a little later

SQL> select UNIQUENESS from dba_indexes where index_name = 'IND';

UNIQUENES
---------
NONUNIQUE

Since the index is nonunique, the optimizer will (or should !?) never go with “INDEX UNIQUE SCAN”.

Let’s now add a primary key.

SQL> alter table table1 add primary key(id);

Table altered.

Since an index on the column ID already exists, Oracle doesn’t attempt to create a new one. It will link the constraint to the existing one. We can confirm it by querying DBA_CONSTRAINTS view. Additionally, the database does not update the index type in the data dictionary.

SQL> select constraint_name, index_name from dba_constraints where table_name = 'TABLE1';

CONSTRAINT_NAME                INDEX_NAME
------------------------------ ------------------------------
SYS_C008559                    IND

SQL> select UNIQUENESS from dba_indexes where index_name = 'IND';

UNIQUENES
---------
NONUNIQUE

What we have so far is that the table has a primary key constraint enforced via an index which Oracle reports as NONUNIQUE (which effectively is not so).

It is interesting to see what index access path will be taken by the optimizer for a query with equality predicate.

select * from table1 where id = 2;
============
Plan Table
============
------------------------------------+-----------------------------------+
| Id  | Operation         | Name    | Rows  | Bytes | Cost  | Time      |
------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT  |         |       |       |     1 |           |
| 1   |  INDEX RANGE SCAN | IND     |     1 |    13 |     0 |           |
------------------------------------+-----------------------------------+

The optimizer reports “INDEX RANGE SCAN”. According to the type of the index in the database dictionary this is expected. However, we definitely know that the index is unique since this is what a primary key constraint is enforced by and unique index should not be causing range scans.

Let’s see what session statistics related to indexes the database reports.

select s.name, value from v$mystat m, v$statname s where s.STATISTIC# = m.STATISTIC#
and s.name like '%index%' 
and value != 0;

NAME                        VALUE
--------------------------- ----------
index range scans           1

So, the statistics also state that the optimizer chooses the “INDEX RANGE SCAN” index access method (this statistics is missing in the Database Reference 19c).

Finally, let’s take a look at the optimizer trace (Access path analysis section only) to see what really happens behind the scenes.

 Access Path: TableScan
    Cost:  2.000631  Resp: 2.000631  Degree: 0
      Cost_io: 2.000000  Cost_cpu: 23521
      Resp_io: 2.000000  Resp_cpu: 23521
  Access Path: index (index (FFS))
    Index: IND
    resc_io: 2.000000  resc_cpu: 0
    ix_sel: 0.000000  ix_sel_with_filters: 1.000000
  Access Path: index (FFS)
    Cost:  2.000000  Resp: 2.000000  Degree: 1
      Cost_io: 2.000000  Cost_cpu: 0
      Resp_io: 2.000000  Resp_cpu: 0
 ****** Costing Index IND
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = INDEX_SCAN
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = INDEX_FILTER
  Access Path: index (UniqueScan)
    Index: IND
    resc_io: 0.000000  resc_cpu: 1050
    ix_sel: 0.004000  ix_sel_with_filters: 0.004000
    Cost: 0.000028  Resp: 0.000028  Degree: 1
 ****** Costing Index IND
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = INDEX_SCAN
  SPD: Return code in qosdDSDirSetup: NOCTX, estType = INDEX_FILTER
  Access Path: index (AllEqUnique)
    Index: IND
    resc_io: 0.000000  resc_cpu: 1050
    ix_sel: 0.004000  ix_sel_with_filters: 0.004000
    Cost: 0.000028  Resp: 0.000028  Degree: 1
 One row Card: 1.000000
  Best:: AccessPath: IndexUnique
  Index: IND
         Cost: 0.000028  Degree: 1  Resp: 0.000028  Card: 1.000000  Bytes: 0.000000

Whola ! In actuality, no “INDEX RANGE SCAN” happens but “INDEX UNIQUE SCAN”. This is confirmed by the access path choice the optimizer ends up with: Best:: AccessPath: IndexUnique (line 30). The “INDEX RANGE SCAN” access path is not even considered as an option. Apparently, the session statistics gets the data from what the optimizer shows up in the execution plan.

In summary, while the optimizer reports “INDEX RANGE SCAN” access method it may not actually be doing so but instead “INDEX UNIQUE SCAN”. The execution plan is not the source of truth in such a case.

Oracle 21c seems to be full of little surprises. Initially appeared in the first release of Oracle 10g and one of the most frequently dealt with “Latch: row cache objects” wait event has disappeared in Oracle 21c. Recall that this latch protects row cache (aka data dictionary cache) entries from simultaneous access by several processes and is acquired before a session can modify row cache objects. Oracle 21c no longer has it:

SQL> select name from v$event_name where name like '%latch: row%';

no rows selected

SQL>

An obvious question is: if this latch is gone, then what replaced it?

To answer this question (or at least to make reasonable assumptions that will take us closer to it) let’s examine other wait events that serve similar purpose.

Firstly, recall that the row cache is made of several caches.

select cache#, parameter from v$rowcache;
--------------------------------------------
3	dc_rollback_segments
1	dc_free_extents
4	dc_used_extents
2	dc_segments
0	dc_tablespaces
5	dc_tablespace_quotas
6	dc_files
10	dc_users
8	dc_objects
17	dc_global_oids
12	dc_constraints
13	dc_sequences
16	dc_histogram_defs
54	dc_sql_prs_errors
32	kqlsubheap_object
..............................

For example, the dc_sequences cache (line 14) store sequences and associated metadata. Each cache is protected by a child latch.

Secondly, it would not make much sense to replace one latch by another. From the other hand, the cache still has to be protected by something. Therefore, it has to be something that is more lightweight than latch. This is mutex (less lightweight is a pin).

Let’s see what mutex related wait events are there in Oracle 21c.

select name from v$event_name where name like '%mutex%'
--------------------------------------------------------
SecureFile fso mutex
SecureFile htbm mutex
SecureFile lhtb mutex
row cache mutex
cursor: mutex X
cursor: mutex S
library cache: mutex X
library cache: bucket mutex X
library cache: dependency mutex X
library cache: mutex S

The row cache mutex wait event (line 6) seems very interesting in this context, doesn’t it? Apparently, this is the one that protects the row cache now.

But one question still remains: why Oracle 19c (and earlier versions as well which I haven’t checked) has both “latch: row cache objects” and “row cache mutex” wait events? An undocumented parameter could be there to dictate the protection mechanism which does not seem to be the case, as far as I’ve researched. Most probably, in this version the row cache is protected by both: partly by latches, partly by mutexes and the former is completely gone in 21c.

One of these days I was configuring result cache in an Oracle 21c database and encountered an unusual behavior. Recall, that result cache which is a slice of memory in the shared pool was introduced in Oracle 11g. It stores results of queries and subsequent ones can reuse it.

Looks like it does not work as documented in Oracle 21c. Two modes are available to configure it: manual by hinting the query and force which will make all queries to store their results in the result cache which is, by the way, not the recommended way. I was experimenting on Ubuntu 8. Here is the scenario (note that result_cache_max_size parameter value which enables or disables result cache is 1792K).

First, let’s create a small table and fill it with some data.

create table table1(id integer, name varchar2(30))
    
insert into table1 values (1, 'Name1');
insert into table1 values (2, 'Name2');
insert into table1 values (3, 'Name3');
commit;

The query is as simple as the following one:

select /*+ RESULT_CACHE */ * from table1;

Plan hash value: 963482612

---------------------------------------------
| Id  | Operation         | Name   | E-Rows |
---------------------------------------------
|   0 | SELECT STATEMENT  |        |        |
|   1 |  TABLE ACCESS FULL| TABLE1 |      3 |

Just to make sure you that the query will use the previously cached results we can execute in multiple times. Still, no effect – plan remains the same.
Tracing the optimizer reveals some details (though not yet clear why so):

Dumping Hints
=============
  atom_hint=(@=0x7f25d42835a8 err=38 resol=1 used=1 token=1192 org=1 lvl=2 txt=RESULT_CACHE ())
********** WARNING: SOME HINTS HAVE ERRORS *********
====================== END SQL Statement Dump ======================

That is, the optimizer considers RESULT_CACHE as a hint and errors out explicitly telling that it cannot parse it: err=38. I’ve tried the FULL hint to compare and for this one err=0. It is easy to see that it is not a configuration related problem, for example, minimum data size to be eligible for caching and etc. since the optimizer says that it faces an error. Moreover, just to exclude size related limitations, if any, I tried with a large data size – no effect.

To be continued…

Imagine a query that faces PGA shortage and heavily spills to temporary tablespace to complete (sorting, hashing and etc.). A typical solution is to tune the query, whereas the following can also act as a way out.
The environment is Oracle 19.3 on Linux 6.4. A test table with ~4 million rows is indexed on one of the columns with temporary tablespace datafiles residing on disk. Index creation requires sorting and the volume of data (4 million rows) forces disk spills. In such a case, 11904 temporary datafile blocks have been allocated and the query completes in 16 seconds.
Then, we load the temporary datafiles in /tmpfs on Linux which caches it in the RAM. Oracle is actually agnostic where the files reside: disk or memory. This time the index creation (started from scratch) spills to 11904 blocks just like before but the query runs two times faster. OS analysis also confirms that the blocks reside in memory this time.

The problem:  A few minute spike on control file sequential read event.
The cause:      A logon storm.
The proof:      A logon trigger querying v$database (that’s a controlfile access). Hence, the wait event.
The solution:  Either remove the query from the trigger or keep the query and find out the reason of excessive logons at that interval given that it will be eliminated on that side. The latter is the correct way to go.

One of databases running on Oracle 12.1 was hanging for some minutes. The top wait event was log file sync. This wait event is posted whenever a user session issues COMMIT or ROLLBACK. A message is then sent to LGWR to flush logs associated with the transaction from the log buffer to redo log files. Redo storage slowness can cause high number of this wait event too. Ultimate blocker in either case is LGWR.
In most cases (but not always), high commit frequency is the cause and should be resolved (decreased) on the application side. That was not the case this time. The reason was the fact that a session (just a single one) issued lots DML statements which generated huge amount of redo. Once the session issued commit, it took quite a long for LGWR to flush redo from the log buffer to the disk. That stalled all other sessions because LGWR was busy and committing sessions were stuck as well. The transaction logic must be changed in the application to issue intermittent commits and not to commit only once when it ends.

One of databases was eventually going completely unresponsive and didn’t resume normal execution until the suspected SQL was manually flushed from the shared pool. AWR indicates that library cache: mutex X wait event prevails. The fact that this mutex is taken whenever the corresponding library cache bucket is changed is well known.

So, the first suspect in case of this wait event is hard parse that can be caused by, for example, undersized shared pool, high version counts and etc. Another cause can be CPU saturation which prevents a thread from jumping on the CPU so that the necessary mutex will be released. This time no hard parses at all. At least, not so much as to worry about.

Looks like there are other cases (not hard parse related) that can cause the library cache bucket mutex to be taken exclusively. For example, execution count of a statement which is held in the parent statement. Whenever a statistics need to be changed the mutex must be held in exclusive mode. This fits very well when we observe that a statement executed ~30,000,000 times, during the other occurrence of the issue  ~28,000,000 times within 10 minutes. Once this loop will be removed/replaced, the issue will most probably be gone.