Search

Top 60 Oracle Blogs

Recent comments

Oakies Blog Aggregator

POUG 2018

I just returned from a great Technical Oracle Conference hosted in Poland by my friends Kamil (@ora600pl) and Luiza (@LuizafromPoland)! They were kind enough to allow me to speak on the topics of SQL Translation Framework and Advanced Query Rewrite. It was my second year in a row to attend this conference and I must say I was extremely impressed by the content and the speakers and the venue and the professional handling of the logistics. Great job all around! I’d highly recommend this conference, so stay tuned for announcements on POUG 2019. Here’s a shot of the Enkitec guys that spoke at the conference: @phurley @JulianDontcheff @fritshoogland

POUG 2018 Enkitec Guyshttp://kerryosborne.oracle-guy.com/files/2018/09/POUG-2018-Enkitec-Guys-... 225w" sizes="(max-width: 768px) 100vw, 768px" />

Stats time

I wrote a note a couple of years ago explaining how I used to get a rough idea (with some errors) of how much time was spent in the overnight stats collection by each object. One of the nice little enhancements that appeared in 12c was the appearance of a couple of functions that can report information about this type of thing, and more. These are the dbms_stats function report_stats_operations() and report_single_stats_operation() with the following definitions:


function report_stats_operations(
        detail_level  varchar2                  default 'TYPICAL',
        format        varchar2                  default 'TEXT', 
        latestN       number                    default null,
        since         timestamp with time zone  default null,
        until         timestamp with time zone  default null,
        auto_only     boolean                   default false,
        container_ids dbms_utility.number_array default dbms_stats.NULL_NUMTAB
) return clob;

function report_single_stats_operation(
        opid         number,
        detail_level varchar2 default 'TYPICAL', 
        format       varchar2 default 'TEXT', 
        container_id number   default null
) return clob;

As you can see, there are lots of options to generating the report of stats operations, and you can check the manuals or $ORACLE_HOME/rdbms/admin/dbmsstat.sql for information about how you can use it. One of the simplest options would be to run from SQL*Plus:

set long 1000000

set pagesize    0
set linesize  255
set trimspool on

column text_line format a254

select
        dbms_stats.report_stats_operations(
                since => sysdate - 3
        ) text_line
from dual
;

Of course you wouldn’t be able to pick the option that limited the report to just the auto gather stats jobs (auto_only => true) as SQL doesn’t a boolean type, so you would have to write a little PL/SQL wrapper to capture just those details. Here’s a sample of the (rather wide) output:


select
        dbms_stats.report_single_stats_operation(25809) text_line
from dual
;

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Operation Id | Operation             | Target                             | Start Time          | End Time            | Status      | Total Tasks | Successful Tasks | Failed Tasks | Active Tasks |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 25811        | purge_stats           |                                    | 08-SEP-18           | 08-SEP-18           | COMPLETED   | 0           | 0                | 0            | 0            |
|              |                       |                                    | 01.47.37.764146 PM  | 01.47.38.405437 PM  |             |             |                  |              |              |
|              |                       |                                    | +01:00              | +01:00              |             |             |                  |              |              |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 25810        | purge_stats           |                                    | 08-SEP-18           | 08-SEP-18           | COMPLETED   | 0           | 0                | 0            | 0            |
|              |                       |                                    | 01.47.35.827284 PM  | 01.47.37.763926 PM  |             |             |                  |              |              |
|              |                       |                                    | +01:00              | +01:00              |             |             |                  |              |              |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 25809        | gather_database_stats | AUTO                               | 08-SEP-18           | 08-SEP-18           | COMPLETED   | 285         | 282              | 3            | 0            |
|              | (auto)                |                                    | 01.46.31.672033 PM  | 01.47.35.826873 PM  |             |             |                  |              |              |
|              |                       |                                    | +01:00              | +01:00              |             |             |                  |              |              |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 25807        | gather_table_stats    | TEST_USER.T1                       | 08-SEP-18           | 08-SEP-18           | COMPLETED   | 1           | 1                | 0            | 0            |
|              |                       |                                    | 12.59.57.704111 PM  | 12.59.57.822695 PM  |             |             |                  |              |              |
|              |                       |                                    | +01:00              | +01:00              |             |             |                  |              |              |

etc.

You’ll notice in this little sample that operation 25809 is an (auto) gather_database_stats operation which ran 285 tasks, failing on 3 and succeeding on 282 – so lets run the “single stats operation” report to find out more.


-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Operation Id | Operation                    | Target | Start Time                      | End Time                        | Status    | Total Tasks | Successful Tasks | Failed Tasks | Active Tasks |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 25809        | gather_database_stats (auto) | AUTO   | 08-SEP-18 01.46.31.672033 PM    | 08-SEP-18 01.47.35.826873 PM    | COMPLETED | 285         | 282              | 3            | 0            |
|              |                              |        | +01:00                          | +01:00                          |           |             |                  |              |              |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|                                                                                                                                                                                                     |
| --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|                                                                                              T A S K S                                                                                              |
| --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | Target                                                         | Type            | Start Time                          | End Time                            | Status                     |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | SYS.RECYCLEBIN$                                                | TABLE           | 08-SEP-18 01.46.50.719791 PM +01:00 | 08-SEP-18 01.46.51.882418 PM +01:00 | COMPLETED                  |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | SYS.RECYCLEBIN$_OBJ                                            | INDEX           | 08-SEP-18 01.46.51.273134 PM +01:00 | 08-SEP-18 01.46.51.773297 PM +01:00 | COMPLETED                  |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | SYS.RECYCLEBIN$_TS                                             | INDEX           | 08-SEP-18 01.46.51.777032 PM +01:00 | 08-SEP-18 01.46.51.787730 PM +01:00 | COMPLETED                  |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
...
...
...
|    | SYS.WRH$_SEG_STAT_PK.WRH$_SEG_ST_3089296639_5150               | INDEX PARTITION | 08-SEP-18 01.47.35.409615 PM +01:00 | 08-SEP-18 01.47.35.483637 PM +01:00 | COMPLETED                  |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | SYS.X$LOGMNR_CONTENTS                                          | TABLE           | 08-SEP-18 01.47.35.520504 PM +01:00 | 08-SEP-18 01.47.35.696953 PM +01:00 | FAILED                     |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | SYS.X$LOGMNR_REGION                                            | TABLE           | 08-SEP-18 01.47.35.699253 PM +01:00 | 08-SEP-18 01.47.35.722545 PM +01:00 | FAILED                     |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|    | SYS.X$DRC                                                      | TABLE           | 08-SEP-18 01.47.35.725003 PM +01:00 | 08-SEP-18 01.47.35.801384 PM +01:00 | FAILED                     |    |
|    ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------    |
|                                                                                                                                                                                                     |
|                                                                                                                                                                                                     |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

I’ve trimmed out most of the 285 entries, of course, showing that the last three in the list failed; but with no indication why they failed. Fortunately we could have called the report with “detail_level => ‘ALL'” – so let’s see what that gives us:

select
        dbms_stats.report_single_stats_operation(
                opid         => 25809,
                detail_level => 'ALL'
        ) text_line
from dual
;

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Operation | Operation             | Target | Start Time      | End Time        | Status    | Total    | Successful | Failed   | Active   | Job Name | Session  | Additional Info             |
| Id        |                       |        |                 |                 |           | Tasks    | Tasks      | Tasks    | Tasks    |          | Id       |                             |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 25809     | gather_database_stats | AUTO   | 08-SEP-18       | 08-SEP-18       | COMPLETED | 285      | 282        | 3        | 0        |          | 250      | Parameters: [block_sample:  |
|           | (auto)                |        | 01.46.31.672033 | 01.47.35.826873 |           |          |            |          |          |          |          | FALSE] [cascade: NULL]      |
|           |                       |        | PM +01:00       | PM +01:00       |           |          |            |          |          |          |          | [concurrent: FALSE]         |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [degree:                    |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | DEFAULT_DEGREE_VALUE]       |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [estimate_percent:          |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | DEFAULT_ESTIMATE_PERCENT]   |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [granularity:               |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | DEFAULT_GRANULARITY]        |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [method_opt:                |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | DEFAULT_METHOD_OPT]         |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [no_invalidate:             |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | DBMS_STATS.AUTO_INVALIDATE] |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [reporting_mode: FALSE]     |
|           |                       |        |                 |                 |           |          |            |          |          |          |          | [stattype: DATA]            |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|                                                                                                                                                                                                     |
| --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|                                                                                              T A S K S                                                                                              |
| --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|       --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------        |
|       | Target       | Type         | Start Time   | End Time     | Status    | Rank  | Job Name | Estimated    | Batching     | Histogram    | Extended     | Reason Code  | Additional   |        |
|       |              |              |              |              |           |       |          | Cost         | Info         | Columns      | Stats        |              | Info         |        |
|       --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------        |
|       | SYS.RECYCLEB | TABLE        | 08-SEP-18 01 | 08-SEP-18 01 | COMPLETED | 1     |          | N/A          | N/A          |              |              | stale stats  |              |        |
|       | IN$          |              | .46.50.71979 | .46.51.88241 |           |       |          |              |              |              |              |              |              |        |
|       |              |              | 1 PM +01:00  | 8 PM +01:00  |           |       |          |              |              |              |              |              |              |        |
|       --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------        |
...
...
...
|       --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------        |
|       | SYS.X$DRC    | TABLE        | 08-SEP-18 01 | 08-SEP-18 01 | FAILED    | 151   |          | N/A          | N/A          |              |              | no stats     | ORA-20000:   |        |
|       |              |              | .47.35.72500 | .47.35.80138 |           |       |          |              |              |              |              |              | Unable to    |        |
|       |              |              | 3 PM +01:00  | 4 PM +01:00  |           |       |          |              |              |              |              |              | analyze      |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | TABLE "SYS". |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | "X$DRC", log |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | miner or     |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | data guard   |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | must be      |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | started      |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | before       |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | analyzing    |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | this fixed   |        |
|       |              |              |              |              |           |       |          |              |              |              |              |              | table"       |        |
|       --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------        |
|                                                                                                                                                                                                     |
|                                                                                                                                                                                                     |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------




So we can now see that stats collection failed on the one object I’ve left in the extract because it’s an X$ object that only exists when LogMiner is running. You’ll notice that the we also get some information about things like input parameters to calls and reasons why objects were selected (“stale stats” in the first item in this list).

It’s a great convenience – but it’s always possible to grumble: I’d rather like to see the elapsed time for each operation, or even a filter to limit the report to any operation that took more than X seconds. However, if I want to do a quick check on a client site I’d rather not have to type in the code to query the base tables by hand.

Modifying tables without losing materialized views

Whilst the ever increasing speed of storage and servers, and features likes In-memory are decreasing the need for large numbers of materialized views in databases, there are still plenty of use cases where they can be a useful performance or integrity tool.

But what if that materialized view takes minutes or hours to build? Then even if it is fast refresh enabled, than fast refresh is no of use if we have to rebuild the entire materialized view from scratch due to an structural change in the underlying table. 

For example, let’s say I have a table and a simple fast refresh materialized view on that table as below:


SQL> create table t(x number(8) primary key);

Table created.

SQL> insert into t values(55);

1 row created.

SQL> create materialized view log on t with primary key, rowid;

Materialized view log created.

SQL> create materialized view mv
  2  build immediate
  3  refresh fast on demand as
  4  select * from t;

Materialized view created.

SQL>
SQL> select * from t;

         X
----------
        55

1 row selected.

SQL> select * from mv;

         X
----------
        55

1 row selected.

SQL> insert into t values (10);

1 row created.

SQL> insert into t values (20);

1 row created.

SQL> commit;

Commit complete.

SQL> select * from t;

         X
----------
        10
        20
        55

3 rows selected.

SQL> select * from mv;

         X
----------
        55

1 row selected.

SQL>
SQL> exec dbms_mview.refresh('mv');

PL/SQL procedure successfully completed.

SQL> select * from mv;

         X
----------
        10
        20
        55

3 rows selected.

For the sake of this discussion, let’s assume the build of materialized takes hours. Naturally we want to avoid having to a rebuild (or do a complete refresh) of that materialized view. But then…the inevitable happens. We need to change the table T. In this case, the values for column X now exceed the limits of the definition.


SQL> insert into t values (123123123);
insert into t values (123123123)
                      *
ERROR at line 1:
ORA-01438: value larger than specified precision allowed for this column

Obviously, this is a trivial fix for the table. We simply alter the column to make it larger (which does not require any downtime or reorganization of the data).


SQL> alter table t modify x number(10);

But all is not well…Having a materialized view means that either the materialized view log, or the materialized view itself may have replicas of that column, so they remain “broken”


SQL> insert into t values (123123123);
insert into t values (123123123)
            *
ERROR at line 1:
ORA-12096: error in materialized view log on "MCDONAC"."T"
ORA-01438: value larger than specified precision allowed for this column

Notice the subtle difference in the error message.  It is not an error on table T, but an error on the materialized view log. You might have the urge to simply jump and run the alter commands on the materialized view log and the materialized view. And you might even find that this approach works. But please note – this approach is not supported, and thus we can’t guarantee that it will (a) work, or (b) not create problems later down the track when you attempt to refresh the view or perform other operations.

But if direct alteration is not support, how do we solve the problem without having to rebuild the entire materialized view from scratch?

The solution here is the option to preserve the materialized view as a standalone table. We can drop the definition of the materialized view but hold on to the table that supports it. Now that it is a standalone table, we can alter the column definition so that it matches our source table T. Notice that before I drop the definition, I perform a final refresh to make sure the materialized is totally up to date – so there is a little bit of coordination required here to make sure that you do not lose any changes that occur to table T during the process.


SQL> exec dbms_mview.refresh('mv');

PL/SQL procedure successfully completed.

SQL> drop materialized view mv preserve table;

Materialized view dropped.

SQL> drop materialized view log on t ;

Materialized view log dropped.

SQL>
SQL> alter table t modify x number(10);

Table altered.

SQL> alter table mv modify x number(10);

Table altered.

We still don’t have our materialized view back though. But we can recreate it without needing a full build cycle, using the PREBUILT table clause.


SQL> create materialized view log on t with PRIMARY KEY, rowid;

Materialized view log created.

SQL>
SQL> create materialized view mv
  2  on prebuilt table
  3  refresh fast  on demand as
  4  select * from t;

Materialized view created.

And we are done! An easy and supported means of altering the materialized view structure without a full rebuild of the data.

Recursive queries on IM_DOMAIN$ at each cursor execution

At POUG 2018 conference I explained join methods by putting gdb breakpoints on the qer (Query Execution Rowsource) functions that are behind the execution plan operations. I was a bit annoyed by several calls when running a Hash Join because of recursive, internal queries on the dictionary. There are a lot of queries on the dictionary during hard parse, but this was at execution time on a query that had already been parsed before. This is new in 12.2 and seems to be related to In-Memory Global Dictionary Join Groups feature, the execution checking and setting up the Join Group aware Hash Join.

However, I must mention that even if this seems to be related with In-Memory I don’t have it enabled here:

Connected to:
Oracle Database 18c Enterprise Edition Release 18.0.0.0.0
Version 18.3.0.0.0
SQL> show parameter inmemory_size
NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
inmemory_size big integer 0

I run the following query on the SCOTT schema to be sure that it is parsed. I force HASH JOIN with hints:

select /*+ leading(EMP DEPT) USE_HASH(DEPT) USE_BASH(BONUS) */ * from DEPT natural join EMP natural join BONUS;

Now starting SQL_TRACE:

column value new_value tracefile
select value from v$diag_info where name='Default Trace File';
VALUE
------------------------------------------------------------
/u01/app/oracle/diag/rdbms/cdb1/CDB1/trace/CDB1_ora_4116.trc
alter session set sql_trace=true;

Then run the same query 10 times:


select /*+ leading(EMP DEPT) USE_HASH(DEPT) USE_BASH(BONUS) */ * from DEPT natural join EMP natural join BONUS;
/
/
/
/
/
/
/
/
/

And tkprof the trace:

alter session set sql_trace=false;
mv &tracefile last.trc ; tkprof last.trc last.txt sort=(execnt)

Here are my 10 executions. The 10 parse calls were soft parses only (no misses in library cache):

select /*+ leading(EMP DEPT) USE_HASH(DEPT) USE_BASH(BONUS) */
* from DEPT natural join EMP natural join BONUS
call     count       cpu    elapsed disk query current  rows
------- ------ -------- ---------- ---- ----- ------- ----
Parse 10 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 10 0.00 0.00 0 120 0 0
------- ------ -------- ---------- ---- ----- ------- ----
total 30 0.00 0.00 0 120 0 0
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 130
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ---------- ---------------------------
0 0 0 HASH JOIN (cr=12 pr=0 pw=0
4 4 4 HASH JOIN (cr=12 pr=0 pw=
4 4 4 TABLE ACCESS FULL EMP (cr
4 4 4 TABLE ACCESS FULL DEPT (c
0 0 0 TABLE ACCESS FULL BONUS (c

Next to it, I can see 10 executions of a SELECT on SYS.IM_DOMAIN$ which is recursive:

SQL ID: 0b639nx4zdzxr Plan Hash: 2321277860
select domain#
from
sys.im_domain$ where objn = :1 and col# = :2
call     count       cpu    elapsed disk query current  rows
------- ------ -------- ---------- ---- ----- ------- ----
Parse 10 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 10 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---- ----- ------- ----
total 30 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Number of plan statistics captured: 1
 (1st) Rows (avg) Rows (max)  Row Source Operation
------ ---------- ---------- ----------------------------------
0 0 0 TABLE ACCESS BY INDEX ROWID IM_DOMAIN$
0 0 0 INDEX UNIQUE SCAN IM_DOMAIN_UK (cr=0

I’ve no idea why this is executed even when IM is disabled. There are probably no bad consequences in performance, especially given that we do no logical reads here (I don’t know by which magic by the way). It is just a surprise to see recursive executions on the dictionary during execution.

How Not to Collect Optimizer Statistics in an Application Engine Program

I was told about a PeopleSoft customer experiencing an Oracle error when collecting statistics during an Application Engine.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">ORA-06533: Subscript beyond count 
ORA-06512: at "SYS.DBMS_STATS"…

It is possibly a manifestation of a database bug. The workaround was not to use AUTO_SAMPLE_SIZE, so instead, this customer initially coded an explicit call to DBMS_STATS.GATHER_TABLE_STATS with a specific sample size.
This blog is not about the bug, but how to manage the workaround.

DO NOT TRY THIS AT HOME!

I think that there are a number of problems with this approach

  1. Using a fixed sample size rather than AUTO_SAMPLE_SIZE should only be considered as a temporary workaround. The new hash-based number-of-distinct-values (NDV) algorithm in Oracle 12c only works with AUTO_SAMPLE_SIZE, and it produces more accurate statistics and runs faster because saves a large sort operation. Coding a fixed sample size into an Application Engine requires a managed change to be made, tested and released into production, and then when the underlying problem is resolved the customisation needs to be removed by the same managed process. 
  2. DBMS_STATS.GATHER_TABLE_STATS implies a commit. That can lead to problems that PeopleSoft avoids by only calling statistics via the %UpdateStats macro and controlling when that macro does and does not execute. 

Committing and Restart Checkpointing in Application Engine

If a restartable Application Engine program fails it rolls back to the last commit point and it can then be restarted from that point. Committing is managed by Application Engine at section and step levels where the program state record is updated accordingly. If an error occurs in a step after the implicit commit in DBMS_STATS, it can result in the data in the application tables being different to where the state record indicates the program can be restarted. The program may not restart, or it could conceivably execute but produce erroneous results.
Committing inside a do while loop, including any other Application Engine program called from inside the loop is suppressed at Application Engine section/step level and therefore the execution of %UpdateStats macro is also suppressed. Otherwise, you could get rogue ORA-01555 Snapshot Too Old errors. Suppression of %UpdateStats is reported in the Application Engine step trace.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">-- 19:07:37.199 .(AEMINITEST.MAIN.LOOP) (Do Select)
%Select(recname) SELECT recname FROM psrecdefn WHERE recname = 'JOB'
/
-- Buffers:
-- 1) JOB
-- 19:07:37.204 Iteration 1 of .(AEMINITEST.MAIN.LOOP) (Do Select) loop

-- 19:07:37.208 .(AEMINITEST.MAIN.LOOP) (SQL)
RECSTATS PS_JOB LOW
/
-- 19:07:37.211 UpdateStats ignored - COMMIT required

-- 19:07:37.212 .(AEMINITEST.MAIN.LOOP) (Do Fetch)

Even a previously uncommitted SQL step can lead to %UpdateStats being suppressed.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">-- 19:07:35.205 .(AEMINITEST.MAIN.Step01) (SQL)
UPDATE PS_AETEMPTBLMGR SET AE_DEDICATED = 1 WHERE 0 = 1
/
-- Row(s) affected: 0

-- 19:07:35.213 .(AEMINITEST.MAIN.Step02) (PeopleCode)

-- 19:07:35.220 .(AEMINITEST.MAIN.US1) (SQL)
RECSTATS PS_JOB LOW
/
-- 19:07:35.227 UpdateStats ignored - COMMIT required

If you code DBMS_STATS.GATHER_TABLE_STATS explicitly, Application Engine will not recognise the step as having committed. In the following example, you can see the %UpdateStats on the last step has been suppressed because it Application Engine does not recognise that the update in the first step has been committed by the call to DBMS_STATS.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">-- 19:12:06.690 .(AEMINITEST.MAIN.Step01) (SQL)
UPDATE PS_AETEMPTBLMGR SET AE_DEDICATED = 1 WHERE 0 = 1
/
-- Row(s) affected: 0
-- 19:12:06.696 .(AEMINITEST.MAIN.Step02) (PeopleCode)
-- 19:12:06.700 .(AEMINITEST.MAIN.GTS) (SQL)
%Execute(/) BEGIN
dbms_stats.gather_table_stats('SYSADM','PS_JOB',estimate_percent=>1); END; /
/
-- Row(s) affected: 1

-- 19:12:09.871 .(AEMINITEST.MAIN.US1) (SQL)
RECSTATS PS_JOB LOW
/
-- 19:12:09.877 UpdateStats ignored - COMMIT required
/

Perhaps, the safest form of this workaround would be to have the step with DBMS_STATS and the immediately preceding step explicitly commit as in the following example.  I have also made the program restartable.  Now restart data is checkpointed, and the %UpdateStats macro executes at step US1.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">Restart Data CheckPointed
/
COMMIT
/

-- 19:20:24.792 .(AEMINITEST.MAIN.GTS) (SQL)
%Execute(/) BEGIN
dbms_stats.gather_table_stats('SYSADM','PS_JOB',estimate_percent=>1); END; /
/

-- Row(s) affected: 1
/
/
Restart Data CheckPointed
/
COMMIT
/

-- 19:20:29.153 .(AEMINITEST.MAIN.US1) (SQL)
RECSTATS PS_JOB LOW
/
-- Row(s) affected: 1
/

However, you have to consider the state the application data after an error, whether you wish to restart or cancel the Application Engine because you can no longer rollback.

Doing the Right Thing

I recommend that:
  • You should only ever collect stats in Application Engine with the %UpdateStats macro that in turn executes the command in the DDL model.
  • From Oracle 11g both PeopleSoft statistics gathering DDL models should be the same and should ultimately call DBMS_STATS without any parameters other than the table name. The default value of ESTIMATE_PERCENT is AUTO_SAMPLE_SIZE.

There are two DDL models in PeopleSoft because %UpdateStats can be invoked with a second parameter to collect the statistics HIGH or LOW. This dates back to Oracle's ANALYZE command that could either compute or estimate statistics (and other database platforms had similar options). Collecting optimizer statistics with ANALYZE has been deprecated for many years, but the command still has other valid uses.  It was superceded by DBMS_STATS in Oracle 8i (released in 1998).
Automatic sample size was introduced in Oracle 9i.  In Oracle 9i and 10g, it was usual to use automatic sample size in the high statistics gathering model and a small fixed sample size in the low model for use on very large tables.  The LOW parameter was specified on %Updatestats in Application Engine programs as necessary.
This approach became redundant from Oracle 11g with the introduction of table preferences. If you need to collect statistics with a specific rather than the automatic sample size or specify any other parameters, then a table preference should be created. Preferences apply wherever statistics are gathered on that table and not overridden in the call of DBMS_STATS., including schema and database-wide operations such as the maintenance window.  If there are multiple places where statistics are collected on a table, a preference assures that the statistics will always be collected will be consistently.
From Oracle 12c, as the new NDV algorithm only works with AUTO_SAMPLE_SIZE, you should always use the default unless you have an overarching reason to the contrary, and then you should use a table preference. This approach does not require any application code change because the preference is an attribute of a table in the database.
I recommend using GFCPSSTATS package, calling it from the DDL model (see previous blog Managing Cost-Based Optimizer Statistics for PeopleSoft). The package also includes a mechanism to specify table preferences in metadata, so that they are automatically instantiated when a table is created or altered by Application Designer, and are applied to every instance of a temporary record.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">gfcpsstats11.ps_stats(p_ownname=>[DBNAME], p_tabname=>[TBNAME]);

Alternatively, just call DBMS_STATS with no additional parameters (other than FORCE, in case you lock statistics on temporary tables) but then you must manage table preferences manually.

#eeeeee; border: 0px solid #000000; font-family: courier new; font-size: 100%; overflow: auto; padding-left: 4px; padding-right: 4px; width: 95%;">DBMS_STATS.GATHER_TABLE_STATS(ownname=>[DBNAME], tabname=>[TBNAME], force=>TRUE);

Further Reading

Subquery Order

From time to time I’ve wanted to optimize a query by forcing Oracle to execute existence (or non-existence) subqueries in the correct order because I know which subquery will eliminate most data most efficiently, and it’s always a good idea to look for ways to eliminate early. I’ve only just discovered (which doing some tests on 18c) that Oracle 12.2.0.1 introduced the /*+ order_subq() */ hint that seems to be engineered to do exactly that.

Here’s a very simple (and completely artificial) demonstration of use.


rem
rem     Script:         122_order_subq.sql
rem     Author:         Jonathan Lewis
rem     Dated:          Sep 2018
rem

create table t1 as select * from all_objects;
create table t2 as select * from all_objects;
create table t3 as select * from all_objects;

create index t2_i1 on t2(object_id);
create index t3_i1 on t3(object_id);

prompt  =============================
prompt  order_subq(@main subq2 subq3)
prompt  =============================

explain plan for
select
        /*+
                qb_name(main)
                no_unnest(@subq2)
                no_unnest(@subq3)
                order_subq(@main subq2 subq3)
        */
        t1.object_name, t1.object_type
from
        t1
where
        exists (
                select
                        /*+ qb_name(subq2) */
                        null
                from    t2
                where   t2.object_id = t1.object_id * 5
        )
and     exists (
                select
                        /*+ qb_name(subq3) */
                        null
                from    t3
                where   t3.object_id = t1.object_id * 13
        )
;

select * from table(dbms_xplan.display(null,null,'outline'));

=============================
order_subq(@main subq2 subq3)
=============================

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2585036931

----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |     1 |    53 | 51090   (1)| 00:00:02 |
|*  1 |  FILTER            |       |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T1    | 61765 |  3196K|   163   (4)| 00:00:01 |
|*  3 |   INDEX RANGE SCAN | T2_I1 |     1 |     5 |     1   (0)| 00:00:01 |
|*  4 |   INDEX RANGE SCAN | T3_I1 |     1 |     5 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
...
      ORDER_SUBQ(@"MAIN" "SUBQ2" "SUBQ3")
...
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( EXISTS (SELECT /*+ NO_UNNEST QB_NAME ("SUBQ2") */ 0 FROM
              "T2" "T2" WHERE "T2"."OBJECT_ID"=:B1*5) AND  EXISTS (SELECT /*+
              NO_UNNEST QB_NAME ("SUBQ3") */ 0 FROM "T3" "T3" WHERE
              "T3"."OBJECT_ID"=:B2*13))
   3 - access("T2"."OBJECT_ID"=:B1*5)
   4 - access("T3"."OBJECT_ID"=:B1*13)

I’ve blocked subquery unnesting for the purposes of the demo and given a query block name to the two subqueries (using a name that identifies the associated table). As you can see, the execution plan uses the subqueries as filter subqueries, operating them in the order I’ve specified in my hint. You can also see that the hint is echoed down into the Outline section of the plan.

It’s possible that this is the plan that the optimizer would have chosen without the order_subq hint, so I ought to see if I can also use the hint to make the subqueries filter in the oppostie order. I happen to know that executing the subquery against t3 is likely to eliminate more rows that executing the subquery against t2. (The “* 13” compared to the “* 5” is significant) so I really want the subqueries to be used in the opposite order anyway – so here’s what happens when I reverse the order in the hint:


prompt  =============================
prompt  order_subq(@main subq3 subq2)
prompt  =============================

explain plan for
select
        /*+
                qb_name(main)
                no_unnest(@subq2)
                no_unnest(@subq3)
                order_subq(@main subq3 subq2)
        */
        t1.object_name, t1.object_type
from
        t1
where
        exists (
                select
                        /*+ qb_name(subq2) */
                        null
                from    t2
                where   t2.object_id = t1.object_id * 5
        )
and     exists (
                select
                        /*+ qb_name(subq3) */
                        null
                from    t3
                where   t3.object_id = t1.object_id * 13
        )
;

select * from table(dbms_xplan.display(null,null,'outline'));

=============================
order_subq(@main subq2 subq3)
=============================

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 3585049451

----------------------------------------------------------------------------
| Id  | Operation          | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |       |     1 |    53 | 51090   (1)| 00:00:02 |
|*  1 |  FILTER            |       |       |       |            |          |
|   2 |   TABLE ACCESS FULL| T1    | 61765 |  3196K|   163   (4)| 00:00:01 |
|*  3 |   INDEX RANGE SCAN | T3_I1 |     1 |     5 |     1   (0)| 00:00:01 |
|*  4 |   INDEX RANGE SCAN | T2_I1 |     1 |     5 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------

Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
...
      ORDER_SUBQ(@"MAIN" "SUBQ3" "SUBQ2")
...
  */

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter( EXISTS (SELECT /*+ NO_UNNEST QB_NAME ("SUBQ3") */ 0 FROM
              "T3" "T3" WHERE "T3"."OBJECT_ID"=:B1*13) AND  EXISTS (SELECT /*+
              NO_UNNEST QB_NAME ("SUBQ2") */ 0 FROM "T2" "T2" WHERE
              "T2"."OBJECT_ID"=:B2*5))
   3 - access("T3"."OBJECT_ID"=:B1*13)
   4 - access("T2"."OBJECT_ID"=:B1*5)

With the modified hint in place the order of the filter subqueries is reversed. Notice how the Predicate section also echoes the ordering of the subqueries.

Footnote

It should be noted that the order_subq() hint doesn’t get mentioned in the 18c SQL Language Reference “Alphabetical List of Hints”. If it were then one of the little oddities that might get a mention is that the optimizer seems to ignore the hint if you disable CPU costing. (not that anyone should be doing that since 10g).

Complex materialized views? Try a table first

Just a quick post today that arose from an AskTOM question a little while back. Over the years and across the evolution of various versions of the Oracle database, the amount of “power” you could pack into a CREATE TABLE statement as grown. For example, I can do a CREATE-TABLE-AS-SELECT, along with a partitioning clause, including an explicit CREATE INDEX command and add constraints all in one atomic operation.



SQL> create table t
  2    (id1,
  3     id2,
  4     owner,
  5     object_name,
  6     constraint t_pk primary key ( id1) using index
  7        ( create index t_pk on t ( id1, owner) )
  8    )
  9  partition by range ( id2 )
 10  (
 11    partition p1 values less than ( 100000 ),
 12    partition p2 values less than ( 200000 )
 13  )
 14  as
 15    select
 16      object_id id1,
 17      object_id id2,
 18      owner,
 19      object_name
 20  from dba_objects
 21  where object_id is not null;

Table created.

That’s pretty cool, but one of the most common times you will be writing DDL that includes a “select * from” as part of the DDL definition, is during the creation of materialized views, because the view text naturally will contain a select statement. Unfortunately, we are not quite as “generous” when it comes to accepting all of the various physical implementation options when it comes to DDL for materialized views. Trying to create a materialized view that matches our table T above is a struggle.


SQL> create materialized view t_mv
  2    (id1,
  3     id2,
  4     owner,
  5     object_name,
  6     constraint t_mv_pk primary key ( id1) using index
  7        ( create index t_mv_pk on t_mv ( id1, owner) )
  8    )
  9  partition by range ( id2 )
 10  (
 11    partition p1 values less than ( 100000 ),
 12    partition p2 values less than ( 200000 )
 13  )
 14  refresh complete on demand
 15  as
 16    select
 17      id1,
 18      id2,
 19      owner,
 20      object_name
 21  from t;
   constraint t_mv_pk primary key ( id1) using index
              *
ERROR at line 6:
ORA-00907: missing right parenthesis


SQL>
SQL> create materialized view t_mv
  2    (id1,
  3     id2,
  4     owner,
  5     object_name,
  6     constraint t_mv_pk primary key ( id1) using index
  7        ( create index t_mv_pk on t_mv ( id1, owner) )
  8    )
  9  refresh complete on demand
 10  partition by range ( id2 )
 11  (
 12    partition p1 values less than ( 100000 ),
 13    partition p2 values less than ( 200000 )
 14  )
 15  as
 16    select
 17      id1,
 18      id2,
 19      owner,
 20      object_name
 21  from t;
   constraint t_mv_pk primary key ( id1) using index
              *
ERROR at line 6:
ORA-00907: missing right parenthesis

When you encounter this limitation, don’t forget that one of the nice things you can do with materialized view creation is pre-create the underlying table with all of its flexibility:



SQL> create table t_mv
  2    (id1,
  3     id2,
  4     owner,
  5     object_name,
  6     constraint t_mv_pk primary key ( id1) using index
  7        ( create index t_mv_pk on t_mv ( id1, owner) )
  8    )
  9  partition by range ( id2 )
 10  (
 11    partition p1 values less than ( 100000 ),
 12    partition p2 values less than ( 200000 )
 13  )
 14  as
 15    select
 16      id1,
 17      id2,
 18      owner,
 19      object_name
 20  from t;

Table created.

And then once that it done, you can use the PREBUILT TABLE clause to create your materialized view which will now satisfy all of the underlying physical structure elements you desired.



SQL> create materialized view t_mv
  2  on prebuilt table
  3  refresh complete on demand
  4  as select
  5      id1,
  6      id2,
  7      owner,
  8      object_name
  9  from t;

Materialized view created.

SQL>
SQL>

ASM Filter Driver — simple test on filtering

Here is a simple test on ASM Filter Driver showing that when filtering is enabled the disks presented to ASM are protected from external writes.

On a 12.2 Grid Infrastructure installation I have my disks labeled with ASM Filter Driver (AFD):

ASMCMD> afd_state
ASMCMD-9526: The AFD state is 'LOADED' and filtering is 'ENABLED' on host 'VM106'
ASMCMD> afd_lsdsk
----------------------------------------------
Label Filtering Path
==============================================
VDI100M0001 ENABLED /dev/sdh
VDI100M0002 ENABLED /dev/sdg
VDI100M0003 ENABLED /dev/sdi
VDI100M0004 ENABLED /dev/sdj
VDI1G0001 ENABLED /dev/sde
VDI1G0002 ENABLED /dev/sdf
VDI1G0003 ENABLED /dev/sdd
VDI1G0004 ENABLED /dev/sdc
VDI1G0005 ENABLED /dev/sdk
VDI1G0006 ENABLED /dev/sdl
...

lsblk is a good way to see all block devices, those mounted as a filesystem, but also those labeled for ASM:

lsblk --paths -o NAME,KNAME,FSTYPE,LABEL,MOUNTPOINT,SIZE,OWNER,GROUP,MODE,ALIGNMENT,MIN-IO,OPT-IO,PHY-SEC,LOG-SEC,ROTA,SCHED,RQ-SIZE,WSAME

I have created a diskgroup, named FRANCK, with only one disk: /dev/sde labeled as VDI1G0001

ASMCMD> lsdsk -G FRANCK
Path
AFD:VDI1G0001

Then I’ve created a tablespace with its datafile on this diskgroup, and a table in this tablespace, inserting ‘Hello Franck!’ which is a string easy to recognize with no need to check the extents block offset:

create tablespace FRANCK datafile '+FRANCK';
create table FRANCK (x varchar2(30)) tablespace FRANCK;
insert into FRANCK values ('Hello Franck!');
commit;
alter system checkpoint;

Nothing is encrypted, the disk is small (1GB) and then I can simply use grep to find my character string:

[root@VM106 ~]# grep --byte-offset --only-matching --text "Hello Franck" /dev/sde
97574895:Hello Franck

I displayed the offset, and can get more detail about the binary data stored around here with od:

[root@VM106 ~]# od -t c --skip-bytes=$(( 97574895 - 10 )) --read-bytes=40 --width=80  /dev/sde
564157745  \0  \0  \0  \0  \0  \0   , 001 001  \r   H   e   l   l   o       F   r   a   n   c   k   ! 001 006   ) 334 006 242  \0  \0 207  \0 200  \a   ( 334   $  \0  \0

As I have the offset, I can easily corrupt the file with dd, writing 5 chr(0) in the middle:

[root@VM106 ~]# dd of=/dev/sde if=/dev/zero seek=$(( 97574895 + 5 )) bs=1 count=5 conv=notrunc
5+0 records in
5+0 records out
5 bytes (5 B) copied, 0.000164038 s, 30.5 kB/s

No errors here. The five write() calls were successful. However we can see the following in /var/log/messages

[root@VM106]# Aug 31 23:19:43 VM106 kernel: Buffer I/O error on device sde, logical block 23821
Aug 31 23:19:43 VM106 kernel: lost page write due to I/O error on sde
Aug 31 23:19:43 VM106 kernel: sd 4:0:2:0: [sde] Incomplete mode parameter data
Aug 31 23:19:43 VM106 kernel: sd 4:0:2:0: [sde] Assuming drive cache: write through
Aug 31 23:19:43 VM106 kernel: sde: unknown partition table

This is the kernel informing us that the writes were lost. This is where AFD has filtered the writes() which were not recognized as what Oracle processes are expected to do. The 23821 logical block is where my offset is: 97574895/4096=23821.99…

If I check back my file, nothing has changed:

[root@VM106 ~]# od -t c --skip-bytes=$(( 97574895 - 10 )) --read-bytes=40 --width=80  /dev/sde
564157745  \0  \0  \0  \0  \0  \0   , 001 001  \r   H   e   l   l   o       F   r   a   n   c   k   ! 001 006   ) 334 006 242  \0  \0 207  \0 200  \a   ( 334   $  \0  \0
564160015

Here I tested with 5 small writes. I got only one set of messages on /var/log/messages. I get the same if I try to create a partition, or a filesystem, on this disk device. This is the goal of ASM Filter Driver: be sure that nobody thinks that the device is not used because they don’t know about ASM, and tries to format it.

Now I disable the filtering to show the normal behaviour:

ASMCMD> afd_filter -d --all
ASMCMD> afd_state
ASMCMD-9526: The AFD state is 'LOADED' and filtering is 'DISABLED' on host 'VM106'
ASMCMD> afd_lsdsk
----------------------------------------------
Label Filtering Path
==============================================
VDI100M0001 DISABLED /dev/sdh
VDI100M0002 DISABLED /dev/sdg
VDI100M0003 DISABLED /dev/sdi
VDI100M0004 DISABLED /dev/sdj
VDI1G0001 DISABLED /dev/sde
...

and run the same writes:

[root@VM106 ~]# dd of=/dev/sde if=/dev/zero seek=$(( 97574895 + 5 )) bs=1 count=5 conv=notrunc
5+0 records in
5+0 records out
5 bytes (5 B) copied, 0.000124124 s, 40.3 kB/s

Here is what I have on /var/log/messages:

Sep  1 22:03:19 VM106 kernel: sd 4:0:2:0: [sde] Incomplete mode parameter data
Sep 1 22:03:19 VM106 kernel: sd 4:0:2:0: [sde] Assuming drive cache: write through
Sep 1 22:03:19 VM106 kernel: sde: unknown partition table

Nothing about I/O error and page write lost.

Without AFD filtering, the diskgroup is corrupt:

[root@VM106 ~]# od -t c --skip-bytes=$(( 97574895 - 10 )) --read-bytes=40 --width=80  /dev/sde
564157745 \0 \0 \0 \0 \0 \0 , 001 001 \r H e l l o \0 \0 \0 \0 \0 c k ! 001 006 ) 334 006 242 \0 \0 207 \0 200 \a ( 334 $ \0 \0

And, of course, those unexpected \0 are detected as corruption:

SQL> select * from franck;
select * from franck
*
ERROR at line 1:
ORA-01578: ORACLE data block corrupted (file # 30, block # 133)
ORA-01110: data file 30: '+FRANCK/CDB1/DATAFILE/franck.256.985734495'

Active Session History in PostgreSQL: blocker and wait chain

While the active session history extension for PostgreSQL is still in beta, some information is added to it.

The pg_active_session_history view is currently made of:

                   View "public.pg_active_session_history"
      Column      |           Type           | Collation | Nullable | Default
------------------+--------------------------+-----------+----------+---------
 ash_time         | timestamp with time zone |           |          |
 datid            | oid                      |           |          |
 datname          | text                     |           |          |
 pid              | integer                  |           |          |
 usesysid         | oid                      |           |          |
 usename          | text                     |           |          |
 application_name | text                     |           |          |
 client_addr      | text                     |           |          |
 client_hostname  | text                     |           |          |
 client_port      | integer                  |           |          |
 backend_start    | timestamp with time zone |           |          |
 xact_start       | timestamp with time zone |           |          |
 query_start      | timestamp with time zone |           |          |
 state_change     | timestamp with time zone |           |          |
 wait_event_type  | text                     |           |          |
 wait_event       | text                     |           |          |
 state            | text                     |           |          |
 backend_xid      | xid                      |           |          |
 backend_xmin     | xid                      |           |          |
 top_level_query  | text                     |           |          |
 query            | text                     |           |          |
 cmdtype          | text                     |           |          |
 queryid          | bigint                   |           |          |
 backend_type     | text                     |           |          |
 blockers         | integer                  |           |          |
 blockerpid       | integer                  |           |          |
 blocker_state    | text                     |           |          |

You could see it as samplings of pg_stat_activity providing more information:

  • ash_time: the sampling time
  • top_level_query: the top level statement (in case PL/pgSQL is used)
  • query: the statement being executed (not normalised, as it is in pg_stat_statements, means you see the values)
  • cmdtype: the statement type (SELECT,UPDATE,INSERT,DELETE,UTILITY,UNKNOWN,NOTHING)
  • queryid: the queryid of the statement which links to pg_stat_statements
  • blockers: the number of blockers
  • blockerpid: the pid of the blocker (if blockers = 1), the pid of one blocker (if blockers > 1)
  • blocker_state: state of the blocker (state of the blockerpid)

Thanks to the queryid field you are able to link the session activity with the sql activity.

The information related to the blocking activity (if any) has been added recently. Why? To easily drill down in case of session being blocked.

Let’s see how we could display some interesting information in case of blocked session(s), for examples:

  • The wait chain
  • The seconds in wait in this chain
  • The percentage of the total wait time that this chain represents

As PostgreSQL provides recursive query and window functions, let’s make use of them to write this query:

postgres@pgu:~$ cat pg_ash_wait_chain.sql
WITH RECURSIVE search_wait_chain(ash_time,pid, blockerpid, wait_event_type,wait_event,level, path)
AS (
          SELECT ash_time,pid, blockerpid, wait_event_type,wait_event, 1 AS level,
          'pid:'||pid||' ('||wait_event_type||' : '||wait_event||') ->'||'pid:'||blockerpid AS path
          from pg_active_session_history WHERE blockers > 0
        union ALL
          SELECT p.ash_time,p.pid, p.blockerpid, p.wait_event_type,p.wait_event, swc.level + 1 AS level,
          'pid:'||p.pid||' ('||p.wait_event_type||' : '||p.wait_event||') ->'||swc.path AS path
          FROM pg_active_session_history p, search_wait_chain swc
          WHERE p.blockerpid = swc.pid and p.ash_time = swc.ash_time and p.blockers > 0
)
select round(100 * count(*) / cnt)||'%' as "% of total wait",count(*) as seconds,path as wait_chain  from (
        SELECT  pid,wait_event,path,sum(count) over() as cnt from (
                select ash_time,level,pid,wait_event,path,count(*) as count, max(level) over(partition by ash_time,pid) as max_level
                FROM search_wait_chain where level > 0 group by ash_time,level,pid,wait_event,path
        ) as all_wait_chain
        where level=max_level
) as wait_chain
group by path,cnt
order by count(*) desc;

Let’s launch this query while only one session is being blocked by another one:

postgres@pgu:~$ psql -f pg_ash_wait_chain.sql
 % of total wait | seconds |                 wait_chain
-----------------+---------+--------------------------------------------
 100%            |      23 | pid:1890 (Lock : transactionid) ->pid:1888
(1 row)

It means that the pid 1890 is waiting since 23 seconds on the transactionid wait event, while being blocked by pid 1888. This wait chain represents 100% of the blocking activity time.

Now another session comes into the game, query the active session history view one more time:

postgres@pgu:~$ psql -f pg_ash_wait_chain.sql
 % of total wait | seconds |                                  wait_chain
-----------------+---------+------------------------------------------------------------------------------
 88%             |     208 | pid:1890 (Lock : transactionid) ->pid:1888
 12%             |      29 | pid:1913 (Lock : transactionid) ->pid:1890 (Lock : transactionid) ->pid:1888
(2 rows)

So we still see our first blocking chain. It is now not the only one (so represents 88% of the blocking activity time).

We can see a new chain that represents 12% of the blocking activity time:

  • pid 1913 (waiting on transactionid) is blocked since 29 seconds by pid 1890 (waiting on transactionid) that is also blocked by pid 1888.

Let’s commit the transaction hold by pid 1888 and launch the query again 2 times:

postgres@pgu:~$ psql -f pg_ash_wait_chain.sql
 % of total wait | seconds |                                  wait_chain
-----------------+---------+------------------------------------------------------------------------------
 57%             |     582 | pid:1890 (Lock : transactionid) ->pid:1888
 40%             |     403 | pid:1913 (Lock : transactionid) ->pid:1890 (Lock : transactionid) ->pid:1888
 3%              |      32 | pid:1913 (Lock : transactionid) ->pid:1890
(3 rows)

postgres@pgu:~$ psql -f pg_ash_wait_chain.sql
 % of total wait | seconds |                                  wait_chain
-----------------+---------+------------------------------------------------------------------------------
 57%             |     582 | pid:1890 (Lock : transactionid) ->pid:1888
 40%             |     403 | pid:1913 (Lock : transactionid) ->pid:1890 (Lock : transactionid) ->pid:1888
 3%              |      33 | pid:1913 (Lock : transactionid) ->pid:1890
(3 rows)

As you can see the first two chains are still displayed (as the query does not filter on ash_time) but are not waiting anymore (seconds does not increase) while the last one (new one) is still waiting (seconds increase).

Remarks

Conclusion

We have seen how the blocking information part of the pg_active_session_history view could help to drill down in case of blocking activity.

Download your SR content from MOS

You may want to keep track of your Oracle Service Requests offline. Or simply be able to read them as simple text. Here is a simple way to download all of them to a simple text file.

First, it is easy to get a list of the Service Requests as an Excel file. Just list them on the GUI. You may choose:

  • The Support Identifiers (CSI) on the right
  • Only SR where you are primary contact or all of them, with the ‘person’ icon
  • Include closed SRs with the red check icon
  • The columns: View -> Columns -> Show all

And then View -> Export to XLS

The service_requests.xls is actually in XML format which is easy to parse, but you can also convert it to CSV. Here I have saved it to service_requests.csv

Then with AWK and LYNX installed here is how to get each SR into text:

awk -F";" 'NR>1{gsub("[()/?%*:|. \\" q qq "]","_");print "lynx -dump -accept-all-cookies -auth=: " q "https://support.oracle.com/epmos/faces/SrDetailPrint?srNumber=" $2 "&print=true&sysmsg=true&sortBy=Newest%20on%20Top" q "> " q $9 "_" $2 "_" $1".txt" q '} q="'" qq='"' service_requests.csv | sh -x

The ideas is to build the file name from the contact ($9), the SR number ($2), and the subject ($1 after translating some characters to ‘_’). And then download using the url used for the ‘print’ view. The authentication is easy with -auth=ID:PASSWD the argument where you pass your Oracle SSO login username and password. Just replace and with yours.

Note that you should not try to run that in parallel or you will get ‘The user has already reached the maximum allowed number of sessions’.