This discussion is archived
7 Replies Latest reply: Feb 5, 2013 1:01 PM by 473487 RSS

Delay when querying from CUBE_TABLE object, what is it?

Laszlo B Newbie
Currently Being Moderated
Hi Guys,

We are using Oracle OLAP 11.2.0.2.0 with an 11g Cube, 7 Dimensions, Compressed and partitioned by Month.

We have run into a performance issue when implementing OBIEE.

The main issue we have is a delay while drilling on a hierarchy. Users have been waiting 7-12 seconds per drill on a hierarchy, and the query is only returning a few cells of data. We have managed to isolate this to slow performing queries on CUBE_TABLE.

For example, the following query returns one cell of data:

-----

SELECT FINSTMNT_VIEW.BASE, FINSTMNT_VIEW.REPORT_TYPE, FINSTMNT_VIEW.COMPANY, FINSTMNT_VIEW.SCENARIO, FINSTMNT_VIEW.PRODUCT, FINSTMNT_VIEW.ACCOUNT, FINSTMNT_VIEW.SITE, FINSTMNT_VIEW.TIME
FROM "SCHEMA1".FINSTMNT_VIEW FINSTMNT_VIEW
WHERE
FINSTMNT_VIEW.REPORT_TYPE IN ('MTD' )
AND FINSTMNT_VIEW.COMPANY IN ('E01' )
AND FINSTMNT_VIEW.SCENARIO IN ('ACTUAL' )
AND FINSTMNT_VIEW.PRODUCT IN ('PT' )
AND FINSTMNT_VIEW.ACCOUNT IN ('APBIT' )
AND FINSTMNT_VIEW.SITE IN ('C010885' )
AND FINSTMNT_VIEW.TIME IN ('JUN11' ) ;

1 Row selected in 4.524 Seconds

-----

Note: FINSTMNT_VIEW is the automatically generated cube view.

CREATE OR REPLACE FORCE VIEW "SCHEMA1"."FINSTMNT_VIEW" ("BASE","REPORT_TYPE", "COMPANY", "SCENARIO", "PRODUCT", "ACCOUNT", "SITE", "TIME")
AS
SELECT "BASE", "REPORT_TYPE", "COMPANY", "SCENARIO", "PRODUCT", "ACCOUNT", "SITE", "TIME"
FROM TABLE(CUBE_TABLE('"SCHEMA1"."FINSTMNT"') ) ;

-----

If we increase the amount of data returned by adding to the query, it only increased the query time by .4 seconds

SELECT FINSTMNT_VIEW.BASE, FINSTMNT_VIEW.REPORT_TYPE, FINSTMNT_VIEW.COMPANY, FINSTMNT_VIEW.SCENARIO, FINSTMNT_VIEW.PRODUCT, FINSTMNT_VIEW.ACCOUNT, FINSTMNT_VIEW.SITE, FINSTMNT_VIEW.TIME
FROM "SCHEMA1".FINSTMNT_VIEW FINSTMNT_VIEW
WHERE
FINSTMNT_VIEW.REPORT_TYPE IN ('MTD' )
AND FINSTMNT_VIEW.COMPANY IN ('E01' )
AND FINSTMNT_VIEW.SCENARIO IN ('ACTUAL' )
AND FINSTMNT_VIEW.PRODUCT IN ('PT' )
AND FINSTMNT_VIEW.ACCOUNT IN ('APBIT' )
AND FINSTMNT_VIEW.SITE IN ('C010885', 'C010886', 'C010891', 'C010892', 'C010887', 'C010888', 'C010897', 'C010893', 'C010890', 'C010894', 'C010896', 'C010899' )
AND FINSTMNT_VIEW.TIME IN ('JUN11' ) ;

12 rows selected - In 4.977 Seconds

-----

If we increase the data returned even more:

SELECT FINSTMNT_VIEW.BASE, FINSTMNT_VIEW.REPORT_TYPE, FINSTMNT_VIEW.COMPANY, FINSTMNT_VIEW.SCENARIO, FINSTMNT_VIEW.PRODUCT, FINSTMNT_VIEW.ACCOUNT, FINSTMNT_VIEW.SITE, FINSTMNT_VIEW.TIME
FROM "SCHEMA1".FINSTMNT_VIEW FINSTMNT_VIEW
WHERE
FINSTMNT_VIEW.REPORT_TYPE IN ('MTD' )
AND FINSTMNT_VIEW.COMPANY IN ('ET', 'E01', 'E02', 'E03', 'E04' )
AND FINSTMNT_VIEW.SCENARIO IN ('ACTUAL' )
AND FINSTMNT_VIEW.PRODUCT IN ('PT', 'P00' )
AND FINSTMNT_VIEW.ACCOUNT IN ('APBIT' )
AND FINSTMNT_VIEW.SITE IN ('C010885', 'C010886', 'C010891', 'C010892', 'C010887', 'C010888', 'C010897', 'C010893', 'C010890', 'C010894', 'C010896', 'C010899' )
AND FINSTMNT_VIEW.TIME IN ('JUN11', 'JUL11', 'AUG11', 'SEP11', 'OCT11', 'NOV11', 'DEC11', 'JAN12') ;

118 rows selected - In 14.213 Seconds

-----

If we take the time for each query and divide by the number of rows, we can see that querying more data results in a much more efficient query:

Time/Rows returned:
1 Row - 4.524
12 Rows - 0.4147
118 Rows - 0.120449153


It seems like there is an initial delay of approx 4 seconds when querying the CUBE_TABLE object. Using AWM to query the same data using LIMIT and RPR is almost instantaneous...

Can anyone explain what this delay is, and if there is any way to optimise the query?

Could it be the AW getting attached before each query?

Big thanks to anyone that can help!
  • 1. Re: Delay when querying from CUBE_TABLE object, what is it?
    Laszlo B Newbie
    Currently Being Moderated
    After running some tests, it's definitely not the AW getting attached for each query... Any Ideas?
  • 2. Re: Delay when querying from CUBE_TABLE object, what is it?
    Shankar S. Journeyer
    Currently Being Moderated
    Not sure if it helps, maybe useful to know. I dont know how you determined that the aw attach time is not the issue.

    ***********
    You can attach the aw before running the queries.

    For OBIEE: You can use the OBIEE "Execute on connect" hook present in Connection Pool "Connection Scripts" tab to run some dbms commands (even olap specific dbms commands) like "SELECT dbms_aw.interp('aw attach aw_name ro') FROM dual". The corresponding detach command via "SELECT dbms_aw.interp('aw detach aw_name') FROM dual" can be executed in "Execute on disconnect".

    Based on some advice provided by David Greenfield a while back regd aw attach mode in CUBE_TABLE based queries:
    If the AW is attached before the cube table call, then it is left attached (i.e. session mode).
    If it is not attached, then it is attached for the duration of the query only.
    OBIEE and olap interaction regd aw attach operations seems to work as follows:
    a) If aw is already attached for obiee connection pool connection (active), then calling query via CUBE_TABLE will not attach/detach the aw (session mode)
    b) If aw is NOT attached prior to execution of request/query against CUBE+TABLE based view then the connection will attach the aw, execute the query and detach the aw once again (query mode)

    It's much better if your queries are running as per scenario a) above.

    ***********
    Another point to consider is that aw attach time can be significantly larger for a privileged user (dba role) who has access to many aws beyond the login/application schema ambit. if your application login is sufficient and you have given dba access to this user/role then it may be worthwhile to test out after revoking the dba grant (explicitly grant other needed privileges).

    ***********

    HTH
    Shankar
  • 3. Re: Delay when querying from CUBE_TABLE object, what is it?
    Laszlo B Newbie
    Currently Being Moderated
    Thanks for the reply.

    To determine if the AW is being attached each query, I inserted some logging into the permit_read program for the AW that I was querying on. It logs a line each time the AW is being attached.

    When running a query from SQL Developer or from OBIEE, I can see that there is only one entry in the log file after running multiple queries, so it seems to attach it for the session.

    I tried your suggestion to attach the AW on connection. I found no change in performance, about 9 seconds per drill in OBIEE.

    Currently, I am building a new AW and mapping to the same source as the original just to make sure there is nothing wrong with the AW itself.
  • 4. Re: Delay when querying from CUBE_TABLE object, what is it?
    Nasar Journeyer
    Currently Being Moderated
    Laszlo,

    I think you are not using OBIEE 11.1.1.5, that is why you are struggling with CUBE_TABLEs. Starting with OBIEE 11.1.1.5, it is so simple now to query from Oracle-OLAP cubes, and we don't use CUBE_TABLEs at all.

    Anyway ....since you are using 11.2.0.2, you should enable query logging and then check CUBE_OPERATIONS_LOG. This will give you a detailed picture of what is going on in the olap engine. For example, it could be that LOOP OPTIMIZATION may not be happening.

    Here are the steps that you do in your SQL client.

    (1). Execute the following.

    being dbms_cube_log.enable(dbms_cube_log.TYPE_OPERATIONS, dbms_cube_log.TARGET_TABLE, dbms_cube_log.LEVEL_MEDIUM); end

    Logging level can be: LEVEL_HIGHEST, LEVEL_HIGH, LEVEL_MEDIUM, LEVEL_LOW, LEVEL_LOWEST


    (2). Execute your olap SQL query

    (3). Execute the following sql

    select * from cube_operations_log
    --where sid = ''  or sql_id = ''
    order by time desc;

    If you know the SID or SQL_ID then you can provide that too.


    Some information that you will see is:

    (1). SUBOPERATION = ‘GDILoopOpt’ row will tell you if LOOP OPTIMIZED is being used. If it is ‘DISABLED’ then figure out why it is. For a cube load that is ok.

    (2). NAME = 'LIMIT_FAST' or 'LIMIT_FULL' or 'LIMIT_INHIER' rows will show the LIMIT commands that were done. You can also see how many members was a particular dimension limited to (by looking at statlen in VALUE column). This is where it limits the cube to a small slice, so that less rows are returned to relational engine.
    NAME = 'CUR_DIM_LENGTH' will also show you the similar thing.

    (3). NAME = 'ROWS_FAILED_FILTER' or 'ROWS_RETURNED' or 'ROWS_READ' rows show useful information about HOW many rows were read from olap to relational engine and then how many “failed” the filter criteria and then finally how many rows were returned.

    (4). ‘predicates pruned’ means that a WHERE clause was fully implemented as limit(s) inside OLAP engine.
  • 5. Re: Delay when querying from CUBE_TABLE object, what is it?
    Laszlo B Newbie
    Currently Being Moderated
    Thanks Nasar,

    I have run a number of queries with logging enabled, the things you mentioned all look good:

    -----

    Loop Optimization: GDILoopOpt     COMPLETED

    Selection filter: FILTER_LIMITS_FAST     7
    ROWS_FAILED_FILTER     0
    ROWS_RETURNED     1

    Predicates: 7 pruned out of 7 predicates

    -----

    The longest action I have seen in the log is the PAGING operation... but I do not see this on all queries.

    Time Total Time OPERATION
    2.263     27.864          PAGING     DYN_PAGEPOOL     TRACE     GREW     9926KB to 59577KB
    1.825     25.601          PAGING     DYN_PAGEPOOL     TRACE     GREW     8274KB to 49651KB
    1.498     23.776          PAGING     DYN_PAGEPOOL     TRACE     GREW     6895KB to 41377KB
    1.232     22.278          PAGING     DYN_PAGEPOOL     TRACE     GREW     5747KB to 34482KB
    1.17     21.046          PAGING     DYN_PAGEPOOL     TRACE     GREW     4788KB to 28735KB
    1.03     19.876          PAGING     DYN_PAGEPOOL     TRACE     GREW     3990KB to 23947KB
    2.808     18.846          PAGING     DYN_PAGEPOOL     TRACE     GREW     3325KB to 19957KB

    -----

    What is strange is that the cube operation log does not account for all of the query time. For example:

    SELECT "BASE_LVL" FROM TABLE(CUBE_TABLE('"EXAMPLE"."FINSTMNT"'))
    WHERE
    "RPT_TYPE" = 'MTD' AND
    "ENTITY" = 'ET' AND
    "SCENARIO" = 'ACTUAL' AND
    "PRODUCT" = 'PT' AND
    "GL_ACCOUNT" = 'APBIT' AND
    "CENTRE" = 'TOTAL' AND
    "TIME" = 'YR09';

    -----

    This query returns in 6.006 seconds using SQL Developer, if I then take the CUBE_OPERATION_LOG for this query and subtract the start time from the end time, I only get 1.67 seconds. This leaves 4.3 seconds unaccounted for... This is the same with the my other queries, see actual time and logged time below:

    Query     Actual     Logged      Variance
    S3     6.006     1.67     4.336
    L1     18.128     13.776     4.352
    S1     4.461     0.203     4.258
    L2     4.696     0.39     4.306
    S2     5.882     1.575     4.307

    Any ideas on what this could be or how I can capture this 4.3 second overhead?

    Your help has been greatly appreciated.
  • 6. Re: Delay when querying from CUBE_TABLE object, what is it?
    Nasar Journeyer
    Currently Being Moderated
    Atleast we know that OLAP engine is returning the resultset quickly.

    You can do AWR report for more detailed information.

    In case, you don't know how to do it, here is more info:

    (1). Make sure that you have Oracle client installed on your machine. OR you have access to a machine where it is installed.

    (2). Goto <ORACLE_HOME>\RDBMS\ADMIN\ directory

    (3). Start a sqlplus session

    (4). execute @awrrpt.sql script
    You may need some privileges to do that.

    (5). Provide the start SNAP_ID and end SNAP_ID for the time when you executed the queries. Select 'html' as the output.

    It takes a minute or two to generate the AWR file.

    Open up the file in a browser, and scroll down to SQL Statistics section.

    You can search on google on how to read an AWR report.

    This is should give you information about where the extra time is spent by the queries.

    .
  • 7. Re: Delay when querying from CUBE_TABLE object, what is it?
    473487 Newbie
    Currently Being Moderated
    As Nasar said, more information can be seen in the cube_operations_log. You can enable it to the high level with:

    exec dbms_cube_log.enable(dbms_cube_log.type_operations, dbms_cube_log.target_table, dbms_cube_log.level_high);

    Then, a query like this should be illuminating:

    SELECT time, name, value
    FROM cube_operations_log
    WHERE operation in ('ROWSOURCE','PAGING') and suboperation in ('STATISTICS','PROGRESS','AW')
    ORDER BY time desc;

    That will list where most of the time is going. Most critically, the lines with FETCH_TIME, LOOP_TIME, CLOSE_SCAN and TOTAL_TIME, but also attach times.

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points