BI Blogs

This web seminar looks at the problems with today’s typical Business Intelligence (BI) environments and what can be done to integrate them, and to get more out of your existing BI investment.

Business Intelligence has historically been left for business units to resolve on their own. This approach often resulted in a morass of disjointed software solutions that answered some questions but frequently created more questions. SAS 9 breaks that paradigm and gives organizations a truly integrated, enterprise class intelligence platform. With SAS 9 you can access data on any platform and deliver results to decision makers through intuitive interfaces. SAS 9 builds enterprise metadata, allowing decision makers to have confidence in the provenance of the facts they are presenting-ensuring decisions made with a level of confidence never before available.

Oracle in talks to buy Siebel
: "Oracle is in talks to buy Siebel Systems for a price tag that could reach $5 Billion The Daily Deal reports. The high-level discussions between the two companies have been confirmed by insiders and industry analysts, but are preliminary and could still break down, according to the news organization."

Fusion: Oracle?s
?Websphere? And More : "Oracle has a lot of middleware products, now they
will all have a common brand name, just as IBM has its Websphere brand. Oracle
Fusion Middleware is a newly created brand for Oracle?s family of middleware
products, which includes Oracle Application Server, Oracle Developer Suite, and
Oracle BPEL Process Manager, among others. Fusion provides a standards-based
approach for deploying SOAs. Using Web services, an Enterprise Service Bus and
Oracle BPEL Process Manager to implement SOAs, customers can integrate
applications and automate business processes."

SAP seals Microsoft deal to
fight Oracle : "SAP has sealed an alliance with Microsoft to co-develop
products in a move that industry analysts have interpreted as a thinly disguised
attack on Oracle. The deal to develop a product set codenamed Mendocino, that
will extend SAP business processes into Microsoft’s Office applications, was
made public at SAP’s Sapphire user conference in Copenhagen yesterday. The joint
development is due to be available through both Microsoft and SAP in the fourth
quarter of 2005. David Bradshaw, principal analyst and practice leader for CRM
at Ovum, said: ‘There were two shots here at Oracle, which is not only SAP’s
arch competitor in business applications but which, ironically, is the most
popular database for running SAP."

Mendocino: The Reason
Microsoft Should Buy Siebel : "Siebel’s strengths can compliment the
shortcomings of Microsoft and assist in further building out the enterprise
software vision they have. Microsoft needs to give Siebel a wake-up call, and
unlike Larry Ellison of Oracle saying in 2004 he would buy Siebel then split it
up into three companies, Microsoft has much more to offer Mr. Siebel —
fulfillment of his original vision of CRM."

One
or two of you might be wondering how I’ve managed to find the time to write so
many articles recently, and the answer to this is down to something you
might have read about
a few weeks ago where our local train service is trialling wireless
broadband internet access on the Brighton to London train each morning. I’ve
been travelling up quite a bit recently and if you get there early (it’s only on
the first three carriages) you can connect up for free for the hour’s journey.
Rather than just sit looking out of the window it’s been a chance to catch up
with email and do a bit of product evaluation. The fact the wireless connection
actually works is a bit of a surprise given the fact that the
trains often themselves
don’t work, but whilst it’s free it’s a pretty good service and makes the
hour’s journey go quite quickly.

Anyway, I’ve been meaning to post a link to this site
for a while. The other week
I mentioned an article
by Jeff Maresh on Supercharging Star Transformations and I also bookmarked at
the time the author’s other paper on
Materialized
Views In Action. If you take a look though at the site that Jeff’s papers
are hosted on though, the Evergreen
Database Technologies Downloadable Library, there’s a whole host of papers
and presentations that would be of interest to DBAs and DW developers, including
ones by Tim Gorman on
Partitioning in
Oracle Data Warehouses and
Tuning PL/SQL using the
DBMS_PROFILER,
Oracle 9i Table Compression and
Optimizing Parallel Query in Oracle 8i (recommended
by Doug Burns in his Tuning
Parallel Execution paper) and others by Jeff Maresh on
Tuning Sort and
Hash Memory Areas,
SQL*Loader Strategies for DW Implementations and
Understanding Locking in Oracle.
All good stuff and well worth a read (especially if you’re going to up London on
the train).

I’ve been playing around with one of the OWB "Paris" betas, and one of the things
that most struck me about this version of OWB compared to previous ones is the
degree to which it utilizes the

OLAP Option. Current and  previous versions of OWB primarily created
relational data warehouses, with the addition of CREATE DIMENSION statements to
help with aggregate navigation. If you wanted to

enable your OWB projects for the OLAP Option you had to use the "OLAP
Bridge" which either created CWM1 metadata for a relational OLAP implementation
or an analytic workspace together with CWM2 metadata for a multidimensional
implementation. Particularly in the case of relational OLAP, you had to do lots
of (non-intuitive) things to make your facts and dimensions work with tools such
as Discoverer for OLAP or BI Beans, such as adding particular suffixes to column
names to create the long and short descriptions needed, and there was no support
whatsoever for the type of materialized view required when using the OLAP
Option. In short, if you use current versions of OWB together with the OLAP
Option, you need to be somewhat "in the know" and carry out lots of post-OWB
steps to make your cubes work properly.

I was pleasantly surprised therefore to note the degree of support that OWB
"Paris" has for creating OLAP Option-ready cubes and dimensions. Some of these
changes that have been put in place to provide this support will however be
initially disorientating for existing OWB developers, and therefore I thought it
worth going through some of what’s coming up and highlight what the point of
this all is.

Just like existing OWB projects, a "Paris" design repository will consist of
a number of projects that contain one or more source and warehouse target
modules. A warehouse target module contains one or more dimensions, together
with one or more cubes containing measures of the same dimensionality.
Dimensions themselves are created using a Dimension Wizard, as before, and one
of the first question the developer is asked is whether the dimension is to be
implemented relationally (ROLAP) or multidimensionally (MOLAP).

I
mentioned this the other week, and the point to note here is that the
decision you make isn’t final; you can change the storage type later on and the
definition of the dimension would still stand. What you are defining at this
point is the logical dimensional model and this applies to both relational and
multidimensional OLAP. The difference here however is that you can create a
multidimensional implementation without going through the intermediate step of
building a relational version, an improvement that’s down to the
new AWXML Java API
that was first introduced with the 10.1.0.3 OLAP "A" patchset.

With existing versions of OWB, the next step would be to specify all the
levels that the dimension uses, across all hierarchies. With OWB "Paris" though,
your next step is to specify all the attributes that will be used by your
dimension, across all levels. One change from existing OWB versions is that you
define a set of attributes, and you then choose to implement each of these at
each of your dimension levels. For example, each level might implement the ID
attribute, plus the NAME and DESCRIPTION attribute - these are all pretty much
mandatory. Then, your might define two more measures, CUSTOMER SEGMENT and
CUSTOMER PROFIT BAND that will then go on to be implemented just by the lowest
CUSTOMER level, and another REGION_HOUSEPRICE_GROWTH_BAND that goes on to be
implemented by just the REGION level.

This idea of having attributes defined in terms of the whole dimension, then
implemented (or not) at each dimension level as required, is something that
comes from the Oracle Express / Oracle OLAP world. When you implement your
dimension relationally, each level-attribute combination turns into a separate
column in the table, and if you implement into an analytic workspace, well
that’s just how attributes are natively stored.

You might also have noticed that the ID and NAME attributes are
specified as Surrogate and Business attributes. What’s happening here is that
each dimension level will have to implement both a surrogate, synthetic ID and a
business ID, meaning for example that your REGION level would not only have the
REGION code from your source system (together optionally with the REGION
DESCRIPTION), it would also have a synthetic region ID generated at load time by
OWB. The reason for this is again down to how dimensions are stored in Express
and analytic workspaces - in a relational star schema dimension, each level is
stored in a separate column, and the IDs for each level member only has to be
unique within the level, whereas analytic workspaces store all dimension level
members within a single dimension object and the level IDs need to be unique
across the whole dimension, hence the need for a synthetic ID at all levels in
the dimension. However, as you’ll see later, OWB "Paris" handles all these
synthetic keys automatically and all you have to bring across is the business
key.

Also, note the significance of the NAME and DESCRIPTION field.
The NAME field is actually the one that you put the business key into (such as
REG10) whilst the DESCRIPTION field is where the descriptive text goes (such as
NORTH-EAST). The NAME field becomes the SHORT_DESCRIPTION whilst the DESCRIPTION
field becomes the LONG_DESCRIPTION, and it’s these that you’ll see in tools like
Discoverer for OLAP when you drill into your dimension hierarchy.

The next page of the wizard lets you define the levels that your
dimension implements. Note the TOTAL_CUSTOMERS level.

Current versions of OWB don’t make you specifically define
TOTAL levels for your dimensions, as you can obtain total figures for a
particular dimension by just omitting the "where" clause in your SELECT
statement. However, OLAP tools such as Discoverer for OLAP and BI Beans (and
before those, tools such as OFA or Express Analyzer) expect a TOTAL level for
each dimension, otherwise you’d not have anywhere in your measure to store data
aggregated up to the TOTAL level;

also, you need to define a specific TOTAL level in the dimension
for it to appear as a selectable hierarchy node in your query builder, as such:

Once you’ve defined your levels, you then get to define which
levels implement which attributes:

In my case the CUSTOMER level will implement all of the
attributes except the REGION_HOUSEPRICE_GROWTH_BAND one, which only applies at
the REGION level, whilst the REGION level will implement the mandatory ID, NAME
and DESCRIPTION ones, the REGION_HOUSEPRICE_GROWTH_ONE one but not the others
which only apply at the CUSTOMER level.

Once you’ve defined your levels and Paris has implemented these
as a default hierarchy, you might then want to move on to the mapping editor to
bring some data into the dimension.   Note that I’ve added a few more
levels into the dimension to illustrate the example:

Remember, what we’re loading here is a

logical model of the dimension, which does not necessarily have to be
implemented as a relational OLAP star schema table. It could be a relational
value-based "a.k.a. parent-child" dimension, or it could be a dimension within
an analytic workspace, which are also value-based. Notice within each level of
the dimension there are items that relate to the level above, so that when you
come to populate the dimension, you populate it level-based and also, if you
need to, value-based as well. By putting this in place Oracle have made it
possible to create mappings that can support data loads into both relational
OLAP dimensions and multidimensional dimensions if needed, but from what I’ve
seen so far if you don’t need to support this, you can just populate the regular
level-based items and leave the value-based ones empty.

Also, note that you don’t now need to explicitly set up
sequences to provide values for the surrogate keys in each dimension level. OWB
Paris sets up the sequences for you and plugs their values into the dimension
mapping "behind the scenes", taking away the need for you to create these
constructs within the mapping.

Another new OLAP Option feature that is pretty special for
relational OLAP users is the support for creating

DBMS_ODM materialized views. Normal materialized views don’t work too well
with tools such as Discoverer for OLAP, as the SQL generated by the OLAP API
uses the GROUPING SETS feature to bring back complete sets of aggregated data, a
feature your regular MVs won’t usually have used. If you want to summarize data
for use with Discoverer for OLAP you have to use DBMS_ODM and up until now
there’s been no GUI tool for doing this.

When you bring up a dimension definition using Paris and you’ve
previously chosen for it to be implemented relationally, you can specify what
dimension / level combinations within the cube are pre-aggregated. Looking at
the SALES cube that uses our CUSTOMER dimension, we can choose to pre-aggregate
at some dimension levels, and have Oracle perform the remaining aggregations on
the fly, very much like you get with analytic workspaces.

Paris will then go off an generate calls to DBMS_ODM to
implement the grouping sets-using materialized view, and register the
aggregations with the OLAP Catalog.

BEGIN
DBMS_ODM.CREATEDIMMV_GS('null','CUSTOMERS','CUSTOMERS_MV.sql','{{PlatformSchema.RTP_TEMP_DIR}}');
DBMS_ODM.CREATEDIMMV_GS('null','PRODUCTS','PRODUCTS_MV.sql','{{PlatformSchema.RTP_TEMP_DIR}}');
DBMS_ODM.CREATEDIMMV_GS('null','CHANNELS','CHANNELS_MV.sql','{{PlatformSchema.RTP_TEMP_DIR}}');
DBMS_ODM.CREATEDIMMV_GS('null','PROMOTIONS','PROMOTIONS_MV.sql','{{PlatformSchema.RTP_TEMP_DIR}}');
DBMS_ODM.CREATEDIMMV_GS('null','TIMES','TIMES_MV.sql','{{PlatformSchema.RTP_TEMP_DIR}}');
DBMS_ODM.CREATEDIMLEVTUPLE('null','SALES');
update SYS.OLAPTABLEVELS set selected = 0 where dimension_name = 'CUSTOMERS' and level_name not in ('PROVINCE','SUBREGION','TOTAL');
update SYS.OLAPTABLEVELS set selected = 0 where dimension_name = 'PRODUCTS' and level_name not in ('TOTAL','SUBCATEGORY');
update SYS.OLAPTABLEVELS set selected = 0 where dimension_name = 'CHANNELS' and level_name not in ('CLASS','CHANNEL');
update SYS.OLAPTABLEVELS set selected = 0 where dimension_name = 'PROMOTIONS' and level_name not in ('CATEGORY');
update SYS.OLAPTABLEVELS set selected = 0 where dimension_name = 'TIMES' and level_name not in ('YEAR','MONTH');
DBMS_ODM.CREATECUBELEVELTUPLE('null','SALES');
DBMS_ODM.CREATEFACTMV_GS('null','SALES','SALES_MV.sql','{{PlatformSchema.RTP_TEMP_DIR}}',true);
CWM2_OLAP_CUBE.set_mv_summary_code('null','SALES','GROUPINGSET');
 END;
/

I thought this was all quite interesting as this is the first
time we’ve seen proper support for the OLAP Option within Warehouse Builder.
Apart from the direct support of multidimensional analytic workspaces (as
covered in more detail in these
two
articles
published earlier) this particular support for the relational implementation of
Oracle OLAP is something pretty special, and something you just can’t really do
with the current generation of OLAP developer tools.

I just discovered Reporting Services Scripter, which seems a very useful tool to move Reporting Services objects between different servers. Thanks to Davide Mauri for the link.

After four years in stealth mode, a new company that applies BI technology to IT governance officially launched yesterday.

To schedule an OWB mapping or process flow to run at a set time, and
optionally to run again after a set interval, without having to deploy it to OEM:

First, log on as the Runtime Repository owner, and run the following script
to create a function called RUN_OWB_JOB. This is a slightly modified version of
the RUN_MY_OWB_STUFF.SQL script downloadable from OTN at

http://www.oracle.com/technology/sample_code/products/warehouse/files/run_my_owb_stuff.sql

create or replace function run_owb_job
              ( p_repos_owner in varchar2 default null
              , p_location_name in varchar2 default null
              , p_task_type in varchar2 default null
              , p_task_name in varchar2 default null
              , p_system_params in varchar2 default '","'
              , p_custom_params in varchar2 default '","'
              , p_oem_friendly in number default 0
              ) return number
is

  l_oem_style          boolean := case (p_oem_friendly)
                                        when 0 then false
                                        else true
                                        end ;
  l_audit_execution_id number;                                  -- Audit Execution Id
  l_audit_result       number := wb_rt_api_exec.RESULT_FAILURE; -- Result Code
  l_audit_result_disp  varchar2(64) := 'FAILURE';               -- Result Display Code

  l_task_type_name     varchar2(64);                            -- Task Type Name
  l_task_type          varchar2(64);                            -- Task Type
  l_task_name          varchar2(64);                            -- Task Name
  l_location_name      varchar2(64);                            -- Location Name

  l_return number ;

  procedure override_input_parameter
  (
    p_audit_execution_id in number,
    p_parameter_name in varchar2,
    p_value in varchar2,
    p_parameter_kind in number
  )
  is
    l_parameter_kind varchar2(64);
  begin

    if p_parameter_kind = wb_rt_api_exec.PARAMETER_KIND_SYSTEM
    then
      l_parameter_kind := 'SYSTEM';
    else
      l_parameter_kind := 'CUSTOM';
    end if;

    dbms_output.put_line('|  ' || p_parameter_name || '%' || l_parameter_kind || '=' || '''' || p_value || '''');

    wb_rt_api_exec.override_input_parameter
    (
      p_audit_execution_id,
      p_parameter_name,
      p_value,
      p_parameter_kind
    );

  end;

  procedure override_input_parameters
  (
    p_audit_execution_id in number,
    p_parameters varchar2,
    p_parameter_kind in number
  )
  is
    l_anchor_offset number := 1;
    l_start_offset number := 1;
    l_equals_offset number;
    l_comma_offset number;
    l_value_offset number;
    l_esc_offset number;
    l_esc_count number;
    l_esc_char varchar2(4);
    l_parameter_name varchar2(4000);
    l_parameter_value varchar2(4000);

    function strip_escape
    (
      p_escapedString varchar2
    )
    return varchar2
    is
      l_strippedString varchar2(4000);
      l_a_char varchar2(4);
      l_b_char varchar2(4);
      l_strip_offset number := 1;
    begin
      loop
        exit when p_escapedString is null or l_strip_offset > length(p_escapedString);
        l_a_char := SUBSTR(p_escapedString, l_strip_offset, 1);
        if l_strip_offset = length(p_escapedString)
        then
          l_strippedString := l_strippedString || l_a_char;
          exit;
        else
          if l_a_char = ''
          then
            l_b_char := SUBSTR(p_escapedString, l_strip_offset + 1, 1);
            if l_b_char = '' or l_b_char = ','
            then
              l_strippedString := l_strippedString || l_b_char;
              l_strip_offset := l_strip_offset + 1;
            end if;
          else
            l_strippedString := l_strippedString || l_a_char;
          end if;
        end if;
        l_strip_offset := l_strip_offset + 1;
      end loop;

      return l_strippedString;
    end;

  begin
    loop
      l_equals_offset := INSTR(p_parameters, '=', l_start_offset);

      exit when l_equals_offset = 0;

      l_start_offset := l_equals_offset + 1;
      loop
        l_comma_offset := INSTR(p_parameters, ',', l_start_offset);

        if l_comma_offset = 0
        then
          l_comma_offset := length(p_parameters) + 1;
          exit;
        else
          l_esc_count := 0;
          l_esc_offset := l_comma_offset - 1;
          loop
            l_esc_char := SUBSTR(p_parameters, l_esc_offset, 1);
            exit when l_esc_char != '';
            l_esc_count := l_esc_count + 1;
            l_esc_offset := l_esc_offset - 1;
          end loop;

          if MOD(l_esc_count, 2) != 0
          then
            l_start_offset := l_comma_offset + 1;
          else
            exit;
          end if;
        end if;
      end loop;

      l_parameter_name := LTRIM(RTRIM(SUBSTR(p_parameters, l_anchor_offset, l_equals_offset - l_anchor_offset)));
      l_parameter_value := strip_escape(SUBSTR(p_parameters, l_equals_offset + 1, l_comma_offset - (l_equals_offset + 1)));

      -- Override Input Parameter
      override_input_parameter(p_audit_execution_id, l_parameter_name, l_parameter_value, p_parameter_kind);

      exit when l_comma_offset >= length(p_parameters)-1;

      l_start_offset := l_comma_offset + 1;
      l_anchor_offset := l_start_offset;

    end loop;
  end;

  procedure override_custom_input_params
  (
    p_audit_execution_id in number,
    p_parameters varchar2
  )
  is
    l_parameter_kind number := wb_rt_api_exec.PARAMETER_KIND_CUSTOM;
  begin
    override_input_parameters(p_audit_execution_id, p_parameters, l_parameter_kind);
    null;
  end;

  procedure override_system_input_params
  (
    p_audit_execution_id in number,
    p_parameters varchar2
  )
  is
    l_parameter_kind number := wb_rt_api_exec.PARAMETER_KIND_SYSTEM;
  begin
    override_input_parameters(p_audit_execution_id, p_parameters, l_parameter_kind);
    null;
  end;

begin

  execute immediate ('alter session set current_schema = ' || p_repos_owner) ;

  --
  -- Initialize Return Code
  --
  l_return := wb_rt_api_exec.RESULT_FAILURE;

  --
  -- Import Parameters
  --
  dbms_output.put_line('Stage 1: Decoding Parameters');
  l_task_type_name := p_task_type ;
  if UPPER(l_task_type_name) = 'PLSQL'
  then
    l_task_type := 'PLSQL';
  elsif UPPER(l_task_type_name) = 'SQL_LOADER'
  then
    l_task_type := 'SQLLoader';
  elsif UPPER(l_task_type_name) = 'PROCESS'
  then
    l_task_type := 'ProcessFlow';
  else
    l_task_type := l_task_type_name;
  end if;
  l_task_name := p_task_name ;
  l_location_name := p_location_name ;
  dbms_output.put_line('|  location_name=' || l_location_name);
  dbms_output.put_line('|  task_type=' || l_task_type);
  dbms_output.put_line('|  task_name=' || l_task_name);

  --
  -- Decode Parameters
  --
  begin
    --
    -- Prepare Execution
    --
    dbms_output.put_line('Stage 2: Opening Task');
    l_audit_execution_id := wb_rt_api_exec.open(l_task_type, l_task_name, l_location_name);
    dbms_output.put_line('|  l_audit_execution_id=' || to_char(l_audit_execution_id));

    commit;

    --
    -- Override Parameters
    --
    dbms_output.put_line('Stage 3: Overriding Parameters');
    override_system_input_params(l_audit_execution_id, p_system_params);
    override_custom_input_params(l_audit_execution_id, p_custom_params);

    --
    -- Execute
    --
    dbms_output.put_line('Stage 4: Executing Task');
    l_audit_result := wb_rt_api_exec.execute(l_audit_execution_id);
    if l_audit_result = wb_rt_api_exec.RESULT_SUCCESS
    then
      l_audit_result_disp := 'SUCCESS';
    elsif l_audit_result = wb_rt_api_exec.RESULT_WARNING
    then
      l_audit_result_disp := 'WARNING';
    elsif l_audit_result = wb_rt_api_exec.RESULT_FAILURE
    then
      l_audit_result_disp := 'FAILURE';
    else
      l_audit_result_disp := 'UNKNOWN';
    end if;
    dbms_output.put_line('|  l_audit_result=' || to_char(l_audit_result) || ' (' || l_audit_result_disp || ')');

    -- Finish Execution
    dbms_output.put_line('Stage 5: Closing Task');
    wb_rt_api_exec.close(l_audit_execution_id);

    commit;

    dbms_output.put_line('Stage 6: Processing Result');
    if l_oem_style
    then
      if l_audit_result = wb_rt_api_exec.RESULT_SUCCESS
      then
        l_return := 0;
      elsif l_audit_result = wb_rt_api_exec.RESULT_WARNING
      then
        l_return := 0;
      else
        l_return := l_audit_result;
      end if;
    else
      l_return := l_audit_result;
    end if;
    dbms_output.put_line('|  exit=' || to_char(l_return));
  exception
    when no_data_found
    then
      raise_application_error(-20001, 'Task not found - Please check the Task Type, Name and Location are correct.');
    end;

  return l_return ;

end;
/

Then, grant EXECUTE on this function to the schema that will submit the job:

SQL> grant execute on run_owb_job to rt92;

Grant succeeded.

Then, assuming your Runtime Repository schema is RTR92, your job you wish to
run is a process flow and is in the WH_PROC_LOC location, the process flow is
called LOAD_T_TIME and you want it to run on 25-APR-2005 at 17:20, run the
following script

declare jobno number;
begin
dbms_job.submit(jobno, 'declare res number; begin res := rtr92.run_my_owb_stuff(''rtr92'',
	''WH_PROC_LOC'',''PROCESS'',''LOAD_T_TIME''); end;', to_date('25-APR-2005 17:20','DD-MON-YYYY HH24:MI'));
commit;
end;
/

You can check what jobs are due to run by querying DBA_JOBS:

select * from all_jobs;

If you want the job to run on a regular basis, you can put an interval after
the scheduled time to run, such as:

declare jobno number;
begin
dbms_job.submit(jobno, 'declare res number; begin res := rtr92.run_my_owb_stuff(''rtr92'',
	''WH_PROC_LOC'',''PROCESS'',''LOAD_T_TIME''); end;', to_date('25-APR-2005 17:20','DD-MON-YYYY HH24:MI'),'SYSDATE +1');
commit;
end;

Note that the second parameter in the DBMS_JOB call is an anonymous PL/SQL
block that calls the RUN_OWB_JOB function. The PL/SQL that is being executed is:

declare res number;
begin
   res := rtr92.run_my_owb_stuff('rtr92','WH_PROC_LOC','PROCESS','LOAD_SALES');
end;

Also if you are using Oracle Database 10g you might want to replace DBMS_JOB
with DBMS_SCHEDULER, which comes with a number of new features and is the “native” scheduling service in OWB “Paris”.

Veritas i3 for J2EE provides customers with end-to-end application management.

If you’re looking to tune an SQL statement or a batch job, a common way to
find out what happened during the execution of the SQL is to run an extended SQL
trace and examine the wait events. But what happens if you are using parallel execution, and all your trace
file contains is the parallel execution wait events that are generally
considered idle events? Your trace file shows how long your query took to run,
and the work involved in controlling the PQ slaves, but the real details of what
took up all the execution time are actually to be found in the corresponding
PQ slave trace files in the BDUMP directory.

To take an example, I create a copy of the SH.SALES table and enable parallel
DML with a degree of parallelism of 2:

SQL*Plus: Release 10.1.0.4.0 - Production on Tue Apr 26 19:49:45 2005

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.1.0.4.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> create table sales_copy as select * from sales;

Table created.

SQL> alter table sales_copy parallel 2;

Table altered.

I then query the parallel_min_servers parameter to make sure some PQ slaves
are available:

SQL> show parameter parallel_min_servers

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
parallel_min_servers                 integer     4
SQL> 

Now, I turn on extended SQL tracing for my session:

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set max_dump_file_size = unlimited;

Session altered.

SQL> alter session set tracefile_identifier = 'px_test1';

Session altered.

SQL> alter session set events = '10046 trace name context forever, level 8';

Session altered.

Now, I run my SELECT statement against the SALES_COPY table and the
PRODUCTS table;

SQL> select p.prod_name, sum(s.amount_sold)
  2  from   products p, sales_copy s
  3  where  p.prod_id = s.prod_id
  4  group by p.prod_name;

PROD_NAME                                          SUM(S.AMOUNT_SOLD)
-------------------------------------------------- ------------------
128MB Memory Card                                           571333.75
17" LCD w/built-in HDTV Tuner                              7189171.77
18" Flat Panel Graphics Monitor                            5498727.81
3 1/2" Bulk diskettes, Box of 100                           370204.56
3 1/2" Bulk diskettes, Box of 50                            254128.79
Adventures with Numbers                                     175563.92
CD-R Mini Discs                                             384553.62
CD-R with Jewel Cases, pACK OF 12                           170405.76
CD-RW, High Speed Pack of 5                                 230233.35
CD-RW, High Speed, Pack of 10                               106468.41
DVD-R Discs, 4.7GB, Pack of 5                                904537.2
...
Y Box                                                       2082330.3

71 rows selected.

Then turn off extended SQL trace:

SQL> alter session set events '10046 trace name context off';

Session altered.

Now, if I format the trace file using TKPROF

C:oracleadminmarkr10gudump>tkprof markr10g_ora_11184_px_test1.trc markr10g_ora_11184_px_test1.txt

TKPROF: Release 10.1.0.4.0 - Production on Tue Apr 26 20:09:12 2005

Copyright (c) 1982, 2004, Oracle.  All rights reserved.

and then take a look at the part of the trace file that relates to my query,
I see the following wait events:

select p.prod_name, sum(s.amount_sold)
from   products p, sales_copy s
where  p.prod_id = s.prod_id
group by p.prod_name

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       1.43        851         87          0           0
Execute      1      0.00       0.07          0          3          0           0
Fetch        6      0.00       3.14          3          4          0          71
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.01       4.65        854         94          0          71

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
     71  PX COORDINATOR  (cr=7 pr=3 pw=0 time=3110386 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
     72  TABLE ACCESS FULL PRODUCTS (cr=4 pr=3 pw=0 time=15278 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Join ACK                                3        0.00          0.00
  PX Deq: Parse Reply                             5        0.02          0.04
  SQL*Net message to client                       6        0.00          0.00
  PX Deq: Execute Reply                          61        0.20          2.79
  PX qref latch                                  31        0.02          0.22
  db file sequential read                         1        0.01          0.01
  db file scattered read                          1        0.00          0.00
  SQL*Net message from client                     6      126.37        126.40
  PX Deq: Signal ACK                              4        0.09          0.10
********************************************************************************

Lots of PX "idle" events, and SQL*Net message to/from client, but not much on
what the query actually waited on. If I take a look in my BDUMP directory
though, I’ve got another four trace files, 2 for the processes that scanned my
SALES_COPY table and two that did the sorting because of the join.

C:oracleadminmarkr10gbdump>dir
 Volume in drive C has no label.
 Volume Serial Number is D47C-241A

 Directory of C:oracleadminmarkr10gbdump

26/04/2005  20:03    <DIR>          .
26/04/2005  20:03    <DIR>          ..
26/04/2005  19:42           349,515 alert_markr10g.log
26/04/2005  20:03             2,353 markr10g_p000_11560.trc
26/04/2005  20:03             2,228 markr10g_p001_6892.trc
26/04/2005  20:03             8,857 markr10g_p002_7568.trc
26/04/2005  20:03             8,312 markr10g_p003_4672.trc
               5 File(s)        371,265 bytes
               2 Dir(s)  28,870,373,376 bytes free

Now if I format the P002 trace file using TKPROF and look at the bit relating
to my SELECT statement, I get the following output:

select p.prod_name, sum(s.amount_sold)
from   products p, sales_copy s
where  p.prod_id = s.prod_id
group by p.prod_name

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.99       3.03       2246       2269          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.99       3.03       2246       2269          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  TABLE ACCESS FULL PRODUCTS (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                          28        0.08          0.23
  PX Deq Credit: send blkd                        3        0.00          0.00
  PX Deq: Table Q Normal                          3        0.01          0.01
  PX qref latch                                   2        0.00          0.00
  direct path read                               74        0.13          1.58

Note the "direct path read" waits. The P003 trace file had the same profile.
Also, if I take a look at the P000 and P001 trace files, which presumably are
doing the sorting, I get the following profile:

select p.prod_name, sum(s.amount_sold)
from   products p, sales_copy s
where  p.prod_id = s.prod_id
group by p.prod_name

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       3.06          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       3.06          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  TABLE ACCESS FULL PRODUCTS (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                           2        2.00          2.92
  PX Deq: Table Q Normal                          3        0.10          0.10
  PX Deq Credit: send blkd                        2        0.00          0.00
  PX qref latch                                   2        0.00          0.01

So what do I do if I need to get the full picture of all the wait events that
have slowed my SQL statement down?

I’m using Oracle 10g, and I remembered from a

previous article I’d written that DBMS_MONITOR allows us to set a "client_id"
that can be used, along with a new utility called TRCSESS, to "stitch together"
trace files that are part of one logical session. Using DBMS_MONITOR, I should
be able to produce a single trace file that contains all the trace data for my
SQL statement.

The first step then is to log on again as SH and this time use DBMS_MONITOR

SQL> exec dbms_session.set_identifier('px_test2');

PL/SQL procedure successfully completed.

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set max_dump_file_size = unlimited;

Session altered.

SQL> alter session set tracefile_identifier = 'px_test2';

Session altered.

SQL> dbms_monitor.client_id_trace_enable(client_id=>'px_test2');
SP2-0734: unknown command beginning "dbms_monit..." - rest of line ignored.
SQL> exec dbms_monitor.client_id_trace_enable(client_id=>'px_test2');

PL/SQL procedure successfully completed.

Note the call to DBMS_SESSION that sets the client_identifier for this
session. This client identifier will be used to tag my SQL statements in the SQL
trace file. Also, ensure that your user has execute permission on DBMS_MONITOR
for this to work.

Now, I run my SELECT statement as before;

SQL> select p.prod_subcategory, sum(s.amount_sold)
  2  from products p, sales_copy s
  3  where p.prod_id = s.prod_id
  4  group by p.prod_subcategory;

PROD_SUBCATEGORY                                   SUM(S.AMOUNT_SOLD)
-------------------------------------------------- ------------------
CD-ROM                                                        3995633
Camcorders                                                  8314815.4
Camera Batteries                                           2143810.36
Camera Media                                               1190971.74
Cameras                                                     6312268.4
Documentation                                              3721699.61
Game Consoles                                               2082330.3
Memory                                                     4948442.05
Monitors                                                   12687899.6
Portable PCs                                               15011642.5
Recordable CDs                                             2075521.27

PROD_SUBCATEGORY                                   SUM(S.AMOUNT_SOLD)
-------------------------------------------------- ------------------
Y Box Games                                                1550229.35
Accessories                                                4057301.26
Bulk Pack Diskettes                                         624333.35
Desktop PCs                                                5635963.08
Home Audio                                                 10537384.2
Modems/Fax                                                 2185350.59
Operating Systems                                          3543725.89
Printer Supplies                                           5244547.32
Recordable DVD Discs                                       1914390.17
Y Box Accessories                                           427571.78

21 rows selected.

and then switch off trace:

SQL> exec dbms_monitor.client_id_trace_disable(client_id=>'px_test2');

PL/SQL procedure successfully completed.

If I take a look at the raw trace file for my main session, the one that
requested all the PX slaves, I can see the client ID within the trace entries:

Dump file c:oracleadminmarkr10gudumpmarkr10g_ora_11704_px_test2.trc
Tue Apr 26 20:27:11 2005
ORACLE V10.1.0.4.0 - Production vsnsta=0
vsnsql=13 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.1.0.4.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU             : 1 - type 586
Process Affinity: 0x00000000
Memory (A/P)    : PH:561M/2047M, PG:1392M/3945M, VA:1665M/2047M
Instance name: markr10g

Redo thread mounted by this instance: 1

Oracle process number: 17

Windows thread id: 11704, image: ORACLE.EXE (SHAD)

*** 2005-04-26 20:27:11.455
*** ACTION NAME:() 2005-04-26 20:27:11.445
*** MODULE NAME:(SQL*Plus) 2005-04-26 20:27:11.445
*** SERVICE NAME:(markr10g) 2005-04-26 20:27:11.445
*** CLIENT ID:(px_test2) 2005-04-26 20:27:11.445
*** SESSION ID:(140.5258) 2005-04-26 20:27:11.445
WAIT #2: nam=’reliable message’ ela= 556 p1=1869466216 p2=1869427312 p3=1870014168
=====================
PARSING IN CURSOR #2 len=72 dep=0 uid=61 oct=47 lid=61 tim=376623839081 hv=4221193623 ad=’6db34444′
BEGIN dbms_monitor.client_id_trace_enable(client_id=>’px_test2′); END;
END OF STMT
EXEC #2:c=10014,e=24730,p=5,cr=1,cu=7,mis=1,r=1,dep=0,og=1,tim=376623839073
WAIT #2: nam=’log file sync’ ela= 660 p1=15 p2=0 p3=0
WAIT #2: nam=’SQL*Net message to client’ ela= 4 p1=1413697536 p2=1 p3=0
*** 2005-04-26 20:31:13.192
WAIT #2: nam=’SQL*Net message from client’ ela= 241736360 p1=1413697536 p2=1 p3=0
=====================
…

And I can find the same in the PX slave trace files,

STAT #1 id=12 cnt=0 pid=7 pos=2 obj=0 op='PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=13 cnt=0 pid=12 pos=1 obj=73335 op='TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)'

*** TRACE DUMP CONTINUED FROM FILE c:oracleadminmarkr10gbdumpmarkr10g_p003_4672.trc ***

*** 2005-04-26 20:31:14.544
*** SERVICE NAME:(markr10g) 2005-04-26 20:31:14.544
*** CLIENT ID:(px_test2) 2005-04-26 20:31:14.544
*** SESSION ID:(150.6373) 2005-04-26 20:31:14.544
WAIT #0: nam='PX Deq: Msg Fragment' ela= 687 p1=268566527 p2=1 p3=0
=====================
PARSING IN CURSOR #1 len=131 dep=1 uid=61 oct=3 lid=61 tim=376866932282 hv=3562105006 ad='6db3f074'
select p.prod_subcategory, sum(s.amount_sold)
from products p, sales_copy s
where p.prod_id = s.prod_id
group by p.prod_subcategory
END OF STMT
PARSE #1:c=0,e=171,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=376866932270
WAIT #1: nam='PX qref latch' ela= 2777 p1=1 p2=1 p3=1849357532

Note that the SQL statement before the client ID was recorded was for my
previous session when I didn’t use a client ID.

Now, I can use the TRCSESS utility to create another trace file that contains
all the SQL statements carried out by the "px_test2" client ID. Where there are
common SQL statements, such as our SELECT statement above, TKPROF will
amalgamate them into a single statement that has multiple executions. TRCSESS is
found in the /bin directory along with TKPROF.

C:oracleadminmarkr10gudump>trcsess output = "markr10g_px_test2_full.trc" clientid = "px_test2" markr10g_ora_11704_px_test2.trc ../bdump/*.trc

Note here that I’ve included my main trace file, and all the PX slave trace
files in the BDUMP directory, as all of them could contain statements tagged
with my client ID.

Now, If I format the "markr10g_px_test2_full.trc" trace file with TKPROF and
take a look at my SELECT statement, I get a view of all of the waits that
contributed to my statement execution time.

select p.prod_subcategory, sum(s.amount_sold)
from products p, sales_copy s
where p.prod_id = s.prod_id
group by p.prod_subcategory

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.04          0          1          0           0
Execute      5      1.75      22.13       4433       4479          0           0
Fetch        3      0.02       5.58          0          4          0          21
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      1.77      27.75       4433       4484          0          21

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  TABLE ACCESS FULL PRODUCTS (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX qref latch                                  29        0.03          0.23
  PX Deq: Execution Msg                          54        2.00         11.43
  PX Deq: Table Q Normal                          6        2.00          2.01
  PX Deq Credit: send blkd                       12        1.99          3.97
  direct path read                              145        0.23          4.27
  PX Deq: Parse Reply                             5        0.12          0.14
  SQL*Net message to client                       3        0.00          0.00
  PX Deq: Execute Reply                          55        0.33          3.14
  SQL*Net message from client                     3       89.12         89.13
  PX Deq: Signal ACK                              7        0.09          0.20
********************************************************************************

You will see that the Parse and Execute counts for the statement are now 5,
reflecting the fact that the main session then called on 4 PX slaves (2 to scan
the SALES_COPY table, 2 to sort the results for the join). There are also a
couple of points to note with this technique:

1. Firstly, the elapsed time figure is the sum of all the elapsed times for
   the main session and the PX slaves, i.e. it won’t reflect the actual time
   that the query took to execute. For this figure, you need to use the elapsed
   time in the main process trace file.
2. This is an import one. If you keep executing the same query, with the
   same client ID, and then use TRCSESS to amalgamate the results, the PX slave
   trace files will still contain entries for this client ID and this statement
   from previous executions. This is because the PX slave sessions sit there
   "permanently" and wait for parallel queries to run, and will write to the
   same trace file irrespective of the session ID of the calling session. What
   this means in reality is that an amalgamated trace file created on say the
   10th execution of a statement for a particular client ID will contain all
   the accumulated waits, execution parse and fetch counts, and elapsed time,
   for all the previous PX executions of this query. The workaround for this is
   to ensure that your client ID is unique each execution, perhaps by just
   adding a number to it each time, either manually or via a sequence.

If you’re looking for specific details on the waits that a particular PX
slave encountered when executing a query, as opposed to the amalgamated (1 x
main) + (4 x PX slaves) details, you can also run TRCSESS on a single PX slave
trace file, to extract just those statements that relate to a particular client
ID. To do this, run TRCSESS against the particular PX slave trace file, like
this:

C:oracleadminmarkr10gudump>trcsess output = "markr10g_p002_7568_full.trc" clientid = "px_test2" markr10g_p002_7568.trc

I’ve used this a couple of times now and it seems to work for me. If I’ve
missed anything or misinterpreted a trace feature, drop me a line and I’ll
incorporate the feedback.

If you’re looking to tune an SQL statement or a batch job, a common way to
find out what happened during the execution of the SQL is to run an extended SQL
trace and examine the wait events. But what happens if you are using parallel execution, and all your trace
file contains is the parallel execution wait events that are generally
considered idle events? Your trace file shows how long your query took to run,
and the work involved in controlling the PQ slaves, but the real details of what
took up all the execution time are actually to be found in the corresponding
PQ slave trace files in the BDUMP directory.

To take an example, I create a copy of the SH.SALES table and enable parallel
DML with a degree of parallelism of 2:

SQL*Plus: Release 10.1.0.4.0 - Production on Tue Apr 26 19:49:45 2005

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.1.0.4.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL> create table sales_copy as select * from sales;

Table created.

SQL> alter table sales_copy parallel 2;

Table altered.

I then query the parallel_min_servers parameter to make sure some PQ slaves
will be created:

SQL> show parameter parallel_min_servers

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
parallel_min_servers                 integer     4
SQL> 

Now, I turn on extended SQL tracing for my session:

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set max_dump_file_size = unlimited;

Session altered.

SQL> alter session set tracefile_identifier = 'px_test1';

Session altered.

SQL> alter session set events = '10046 trace name context forever, level 8';

Session altered.

Now, I run my SELECT statement against the SALES_COPY table and the
PRODUCTS_DIM table;

SQL> select p.prod_name, sum(s.amount_sold)
  2  from   products p, sales_copy s
  3  where  p.prod_id = s.prod_id
  4  group by p.prod_name;

PROD_NAME                                          SUM(S.AMOUNT_SOLD)
-------------------------------------------------- ------------------
128MB Memory Card                                           571333.75
17" LCD w/built-in HDTV Tuner                              7189171.77
18" Flat Panel Graphics Monitor                            5498727.81
3 1/2" Bulk diskettes, Box of 100                           370204.56
3 1/2" Bulk diskettes, Box of 50                            254128.79
Adventures with Numbers                                     175563.92
CD-R Mini Discs                                             384553.62
CD-R with Jewel Cases, pACK OF 12                           170405.76
CD-RW, High Speed Pack of 5                                 230233.35
CD-RW, High Speed, Pack of 10                               106468.41
DVD-R Discs, 4.7GB, Pack of 5                                904537.2
...
Y Box                                                       2082330.3

71 rows selected.

Then turn off extended SQL trace:

SQL> alter session set events '10046 trace name context off';

Session altered.

Now, if I format the trace file using TKPROF

C:oracleadminmarkr10gudump>tkprof markr10g_ora_11184_px_test1.trc markr10g_ora_11184_px_test1.txt

TKPROF: Release 10.1.0.4.0 - Production on Tue Apr 26 20:09:12 2005

Copyright (c) 1982, 2004, Oracle.  All rights reserved.

and then take a look at the part of the trace file that relates to my query,
I see the following wait events:

select p.prod_name, sum(s.amount_sold)
from   products p, sales_copy s
where  p.prod_id = s.prod_id
group by p.prod_name

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       1.43        851         87          0           0
Execute      1      0.00       0.07          0          3          0           0
Fetch        6      0.00       3.14          3          4          0          71
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.01       4.65        854         94          0          71

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
     71  PX COORDINATOR  (cr=7 pr=3 pw=0 time=3110386 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
     72  TABLE ACCESS FULL PRODUCTS (cr=4 pr=3 pw=0 time=15278 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Join ACK                                3        0.00          0.00
  PX Deq: Parse Reply                             5        0.02          0.04
  SQL*Net message to client                       6        0.00          0.00
  PX Deq: Execute Reply                          61        0.20          2.79
  PX qref latch                                  31        0.02          0.22
  db file sequential read                         1        0.01          0.01
  db file scattered read                          1        0.00          0.00
  SQL*Net message from client                     6      126.37        126.40
  PX Deq: Signal ACK                              4        0.09          0.10
********************************************************************************

Lots of PX "idle" events, and SQL*Net message to/from client, but not much on
what the query actually waited on. If I take a look in my BDUMP directory
though, I’ve got another four trace files, 2 for the processes that scanned my
SALES_COPY table and two that did the sorting because of the join.

C:oracleadminmarkr10gbdump>dir
 Volume in drive C has no label.
 Volume Serial Number is D47C-241A

 Directory of C:oracleadminmarkr10gbdump

26/04/2005  20:03    <DIR>          .
26/04/2005  20:03    <DIR>          ..
26/04/2005  19:42           349,515 alert_markr10g.log
26/04/2005  20:03             2,353 markr10g_p000_11560.trc
26/04/2005  20:03             2,228 markr10g_p001_6892.trc
26/04/2005  20:03             8,857 markr10g_p002_7568.trc
26/04/2005  20:03             8,312 markr10g_p003_4672.trc
               5 File(s)        371,265 bytes
               2 Dir(s)  28,870,373,376 bytes free

Now if I format the P002 trace file using TKPROF and look at the bit relating
to my SELECT statement, I get the following output:

select p.prod_name, sum(s.amount_sold)
from   products p, sales_copy s
where  p.prod_id = s.prod_id
group by p.prod_name

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.99       3.03       2246       2269          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.99       3.03       2246       2269          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  TABLE ACCESS FULL PRODUCTS (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                          28        0.08          0.23
  PX Deq Credit: send blkd                        3        0.00          0.00
  PX Deq: Table Q Normal                          3        0.01          0.01
  PX qref latch                                   2        0.00          0.00
  direct path read                               74        0.13          1.58

Note the "direct path read" waits. The P003 trace file had the same profile.
Also, if I take a look at the P000 and P001 trace files, which presumably are
doing the sorting, I get the following profile:

select p.prod_name, sum(s.amount_sold)
from   products p, sales_copy s
where  p.prod_id = s.prod_id
group by p.prod_name

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       3.06          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       3.06          0          0          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  PX COORDINATOR  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  SORT GROUP BY (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0  HASH JOIN  (cr=0 pr=0 pw=0 time=0 us)
      0   BUFFER SORT (cr=0 pr=0 pw=0 time=0 us)
      0    PX RECEIVE  (cr=0 pr=0 pw=0 time=0 us)
      0  TABLE ACCESS FULL PRODUCTS (cr=0 pr=0 pw=0 time=0 us)(Orphan Entry)
      0   PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: Execution Msg                           2        2.00          2.92
  PX Deq: Table Q Normal                          3        0.10          0.10
  PX Deq Credit: send blkd                        2        0.00          0.00
  PX qref latch                                   2        0.00          0.01

So what do I do if I need to get the full picture of all the wait events that
have slowed my SQL statement down?

I’m using Oracle 10g, and I remembered from a

previous article I’d written that DBMS_MONITOR allows us to set a "client_id"
that can be used, along with a new utility called TRCSESS, to "stitch together"
trace files that are part of one logical session. Using DBMS_MONITOR, I should
be able to produce a single trace file that contains all the trace data for my
SQL statement.

The first step then is to log on again as SH and this time use DBMS_MONITOR

SQL> exec dbms_session.set_identifier('px_test2');

PL/SQL procedure successfully completed.

SQL> alter session set timed_statistics = true;

Session altered.

SQL> alter session set max_dump_file_size = unlimited;

Session altered.

SQL> alter session set tracefile_identifier = 'px_test2';

Session altered.

SQL> dbms_monitor.client_id_trace_enable(client_id=>'px_test2');
SP2-0734: unknown command beginning "dbms_monit..." - rest of line ignored.
SQL> exec dbms_monitor.client_id_trace_enable(client_id=>'px_test2');

PL/SQL procedure successfully completed.

Note the call to DBMS_SESSION that sets the client_identifier for this
session. This client identifier will be used to tag my SQL statements in the SQL
trace file. Also, ensure that your user has execute permission on DBMS_MONITOR
for this to work.

Now, I run my SELECT statement as before;

SQL> select p.prod_subcategory, sum(s.amount_sold)
  2  from products p, sales_copy s
  3  where p.prod_id = s.prod_id
  4  group by p.prod_subcategory;

PROD_SUBCATEGORY                                   SUM(S.AMOUNT_SOLD)
-------------------------------------------------- ------------------
CD-ROM                                                        3995633
Camcorders                                                  8314815.4
Camera Batteries                                           2143810.36
Camera Media                                               1190971.74
Cameras                                                     6312268.4
Documentation                                              3721699.61
Game Consoles                                               2082330.3
Memory                                                     4948442.05
Monitors                                                   12687899.6
Portable PCs                                               15011642.5
Recordable CDs                                             2075521.27

PROD_SUBCATEGORY                                   SUM(S.AMOUNT_SOLD)
-------------------------------------------------- ------------------
Y Box Games                                                1550229.35
Accessories                                                4057301.26
Bulk Pack Diskettes                                         624333.35
Desktop PCs                                                5635963.08
Home Audio                                                 10537384.2
Modems/Fax                                                 2185350.59
Operating Systems                                          3543725.89
Printer Supplies                                           5244547.32
Recordable DVD Discs                                       1914390.17
Y Box Accessories                                           427571.78

21 rows selected.

and then switch off trace:

SQL> exec dbms_monitor.client_id_trace_disable(client_id=>'px_test2');

PL/SQL procedure successfully completed.

If I take a look at the raw trace file for my main session, the one that
requested all the PX slaves, I can see the client ID within the trace entries:

Dump file c:oracleadminmarkr10gudumpmarkr10g_ora_11704_px_test2.trc
Tue Apr 26 20:27:11 2005
ORACLE V10.1.0.4.0 - Production vsnsta=0
vsnsql=13 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.1.0.4.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU             : 1 - type 586
Process Affinity: 0x00000000
Memory (A/P)    : PH:561M/2047M, PG:1392M/3945M, VA:1665M/2047M
Instance name: markr10g

Redo thread mounted by this instance: 1

Oracle process number: 17

Windows thread id: 11704, image: ORACLE.EXE (SHAD)

*** 2005-04-26 20:27:11.455
*** ACTION NAME:() 2005-04-26 20:27:11.445
*** MODULE NAME:(SQL*Plus) 2005-04-26 20:27:11.445
*** SERVICE NAME:(markr10g) 2005-04-26 20:27:11.445
*** CLIENT ID:(px_test2) 2005-04-26 20:27:11.445
*** SESSION ID:(140.5258) 2005-04-26 20:27:11.445
WAIT #2: nam=’reliable message’ ela= 556 p1=1869466216 p2=1869427312 p3=1870014168
=====================
PARSING IN CURSOR #2 len=72 dep=0 uid=61 oct=47 lid=61 tim=376623839081 hv=4221193623 ad=’6db34444′
BEGIN dbms_monitor.client_id_trace_enable(client_id=>’px_test2′); END;
END OF STMT
EXEC #2:c=10014,e=24730,p=5,cr=1,cu=7,mis=1,r=1,dep=0,og=1,tim=376623839073
WAIT #2: nam=’log file sync’ ela= 660 p1=15 p2=0 p3=0
WAIT #2: nam=’SQL*Net message to client’ ela= 4 p1=1413697536 p2=1 p3=0
*** 2005-04-26 20:31:13.192
WAIT #2: nam=’SQL*Net message from client’ ela= 241736360 p1=1413697536 p2=1 p3=0
=====================
…

And I can find the same in the PX slave trace files,

STAT #1 id=12 cnt=0 pid=7 pos=2 obj=0 op='PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us)'
STAT #1 id=13 cnt=0 pid=12 pos=1 obj=73335 op='TABLE ACCESS FULL SALES_COPY (cr=0 pr=0 pw=0 time=0 us)'

*** TRACE DUMP CONTINUED FROM FILE c:oracleadminmarkr10gbdumpmarkr10g_p003_4672.trc ***

*** 2005-04-26 20:31:14.544
*** SERVICE NAME:(markr10g) 2005-04-26 20:31:14.544
*** CLIENT ID:(px_test2) 2005-04-26 20:31:14.544
*** SESSION ID:(150.6373) 2005-04-26 20:31:14.544
WAIT #0: nam='PX Deq: Msg Fragment' ela= 687 p1=268566527 p2=1 p3=0
=====================
PARSING IN CURSOR #1 len=131 dep=1 uid=61 oct=3 lid=61 tim=376866932282 hv=3562105006 ad='6db3f074'
select p.prod_subcategory, sum(s.amount_sold)
from products p, sales_copy s
where p.prod_id = s.prod_id
group by p.prod_subcategory
END OF STMT
PARSE #1:c=0,e=171,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=376866932270
WAIT #1: nam='PX qref latch' ela= 2777 p1=1 p2=1 p3=1849357532

Note that the SQL statement before the client ID was recorded was for my
previous session when I didn’t use a client ID.

Now, I can use the TRCSESS utility to create another trace file that contains
all the SQL statements carried out by the "px_test2" client ID. Where there are
common SQL statements, su