Implementing Index Compression (and other Physical Storage Options) via Application Designer

There are some performance improvements that require physical storage options to be set on tables or indexes.
One particular technique that I will take as an example for this article is index compression.  A good example in PeopleSoft is the tree node table, PSTREENODE.  It drives many security and hierarchical queries.  It is not updated very frequently, only as new trees are brought on.  Many of the indexes are good candidates for compression.
This compression works by storing repeated column values only one per index leaf block.  Each distinct set of values in the columns up to the prefix length are stored in a symbol table.  The choice of prefix length can significantly affect compression.  Oracle can calculate the optimal prefix length using

ANALYZE INDEX … VALIDATE STRUCTURE

I have written this script to make it slightly easier, calc_opt_comp.sql.  This is the output on my demo database, but I get similar results on production systems.

                                          Optimal
                                      Compression                       Weighted
                                           Prefix               Current  Average
Table Name         Index Name              Length FREQ PARTS     Blocks Saving %
------------------ ------------------ ----------- ---- ----- ---------- --------
PSTREENODE         PSAPSTREENODE                4    1     0        280     39.0
                   PSBPSTREENODE                3    1     0        264     30.0
                   PSCPSTREENODE                1    1     0        120      7.0
                   PSDPSTREENODE                4    1     0        256     61.0
                   PSFPSTREENODE                2    1     0        256     67.0
                   PSGPSTREENODE                3    1     0        400     49.0
                   PS_PSTREENODE                4    1     0        256     44.0 

However, I want to make sure that should the table need to be rebuilt in the future, PeopleTools will generate the DDL with the appropriate settings.  The same principle would also apply to any other physical storage option.  I would always recommend that the compression prefix lengths be incorporated into the PeopleTools DDL override in Application Designer (figure 1).  While you could extend the DDL model and add another override for compression, I just append it to the PCTFREE setting.

Figure 1. Index DDL Override

However, there is a catch.  PeopleTools has never examined DDL overrides when determining whether there is a difference between the PeopleSoft and database data dictionaries, even though that comparison must be platform-specific.  DDL overrides and DDL models are just strings held in the PeopleTools tables.  They can be extended (or even removed) by customers.  I assume this is the reason; it was not felt possible to reliably check them,
So, if the build settings (figure 2) are 'recreate index only if modified', which is the default, Application Designer will not generate a DDL script, nor execute any DDL.

Figure 2. Build Settings

The workaround has always been to set the index creation option in the build settings to 'recreate index if it already exists'.  However, we then discover the override doesn't appear in the DDL.  As Application Designer has not detected a difference between PeopleTools and the database, it has instead used the Oracle DBMS_METADATA package to generate the storage clause from the index that exists in the database.  Hence the DDL contains additional keywords, not in the PeopleSoft DDL model.

CREATE UNIQUE  INDEX PS_PSTREENODE ON PSTREENODE (SETID,
   SETCNTRLVALUE,
   TREE_NAME,
   EFFDT,
   TREE_NODE_NUM,
   TREE_NODE,
   TREE_BRANCH) 
  PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS 
  STORAGE(INITIAL 40960 NEXT 106496 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "PSINDEX"
/
ALTER INDEX PS_PSTREENODE NOPARALLEL LOGGING
/

I have only checked this behaviour on PeopleTools 8.54, but the use of DBMS_METADATA was introduced in PeopleTools 8.51, so this problem has probably existed since then.

SELECT dbms_metadata.get_ddl('INDEX','PS_PSTREENODE')
FROM dual

DBMS_METADATA.GET_DDL('INDEX','PS_PSTREENODE')
--------------------------------------------------------------------------------
  CREATE UNIQUE INDEX "SYSADM"."PS_PSTREENODE" ON "SYSADM"."PSTREENODE" ("SETID"
, "SETCNTRLVALUE", "TREE_NAME", "EFFDT", "TREE_NODE_NUM", "TREE_NODE", "TREE_BRANCH")
  PCTFREE 10 INITRANS 2 MAXTRANS 255 COMPUTE STATISTICS
  STORAGE(INITIAL 40960 NEXT 106496 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "PSINDEX"

However, if I drop the index and then regenerate the DDL script in Application Designer,

DROP INDEX ps_pstreenode
/

PeopleTools generates the create index with the compression specified in the PeopleTools table.

…
CREATE UNIQUE  INDEX PS_PSTREENODE ON PSTREENODE (SETID,
   SETCNTRLVALUE,
   TREE_NAME,
   EFFDT,
   TREE_NODE_NUM,
   TREE_NODE,
   TREE_BRANCH) TABLESPACE PSINDEX STORAGE (INITIAL 40000 NEXT 100000
 MAXEXTENTS UNLIMITED PCTINCREASE 0) PCTFREE 0 COMPRESS 4 PARALLEL
 NOLOGGING
/
ALTER INDEX PS_PSTREENODE NOPARALLEL LOGGING
/
…

Rather than go through the business of dropping the index so you can then generate the correct script to then recreate the index, I would suggest just implementing the change manually by rebuilding the indexes.

ALTER INDEX PSAPSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 4;
ALTER INDEX PSBPSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 3;
ALTER INDEX PSCPSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 1;
ALTER INDEX PSDPSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 4;
ALTER INDEX PSFPSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 2;
ALTER INDEX PSGPSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 3;
ALTER INDEX PS_PSTREENODE REBUILD TABLESPACE PSINDEX COMPRESS 4;

Conclusion

This makes the business of implementing physical attributes through Application Designer much more complicated.  I would still recommend recording the settings in Application Designer, if only because it provides documentation, but then it may be easier to implement the changes manually.

Disappearing Histograms

In general, once you have a histogram on a column you keep it.  However, this is not because DBMS_STATS simply maintains it because it is there, but because it is still appropriate to have it based on the column workload usage.
Since Oracle 10g, the default method for collecting histograms is AUTO, which means that Oracle determines whether to collect a histogram based on data distribution and the workload of the column.
What is less well known (including to me until recently), is that histograms can be removed if there is no column workload to justify them.

This can be an issue when for some reason you have imported statistics on a freshly rebuilt table with no column usage.  I think the first two scenarios are the most likely:

1. Export statistics.  Reorganize table by recreation.  Import statistics.  
2. On a test database, import cut down data set, but with full volume production statistics.
3. Column usage is deleted.

In all cases, the histograms will be removed by the maintenance window statistics job if column usage has not built up again.  This can lead to changes in the execution plan and performance problems.  When this happens in a production system, it is often a transient problem until the column usage builds up and the histograms are usually reinstated when statistics are next collected.
In the third scenario you have the potential to refer back to any statistics history (see Mauro Pagano's blog Histograms Come Histograms Go), but that will not be the case where the original table has been dropped.

Demonstration

I will create a table and populate it.  The data in columns A, B and C is perfectly uniform, only column SKEW is skewed.

drop table t purge
/
create table t
(a number
,b number
,c number
,skew number
)
/
insert into t 
with x as (
select rownum n from dual connect by level <= 10
)
select a.n, b.n, c.n, a.n*b.n*c.n 
from x a, x b, x c
/

Note that I have collected statistics with SKEWONLY. So statistics will be collected if the data distribution is skewed irrespective of the usage of the column.

REM collect stats and histograms on everything
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT' ,tabname=>'T' ,method_opt=>'FOR ALL COLUMNS SIZE SKEWONLY'
 );
end;
/
REM check for histogram
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from   dba_tab_col_statistics
where  owner = 'SCOTT'
and    table_name = 'T'
/

Now I have histograms on all columns, even though the data in columns A, B, and C is not skewed at all but is perfectly uniform,  This shows the value of the column usage feature in limiting the excessive collection of histograms.

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------                                                 
T     A            10     0 FREQUENCY      10    1000
T     B            10     0 FREQUENCY      10    1000
T     C            10     0 FREQUENCY      10    1000
T     SKEW        120     0 FREQUENCY     120    1000

At this point, there is no column usage. So when I collect statistics the histogram will all disappear.

REM check no column usage
select *
from   sys.col_usage$ u
where  obj# IN(select object_id 
               from  dba_objects 
               WHERE owner = 'SCOTT'
               AND   object_name = 'T'
               AND   object_Type = 'TABLE')
/
REM collect the stats with default col usage
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT',tabname=>'T');
end;
/
REM check for histogram - should have gone with no col usage
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from   dba_tab_col_statistics
where  owner = 'SCOTT'
and    table_name = 'T'
/

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------
T     A            10     0 NONE            1    1000
T     B            10     0 NONE            1    1000
T     C            10     0 NONE            1    1000
T     SKEW        120     0 NONE            1    1000

Sure enough, there are now no histograms on the columns, and there is just a single bucket on each column. So now I will generate some column usage, I will do some equality queries on the column SKEW, and I will flush the monitoring information to the data dictionary.

set serveroutput off
declare
 z NUMBER;
begin
 for a in 1..10 loop
  for b in 1..10 loop
   for c in 1..10 loop
    EXECUTE IMMEDIATE 'SELECT '||'/*'||(a*b*c)||'*/'||' count(*) FROM t where skew = '||(a*b*c) INTO z;
   end loop;
  end loop;
 end loop;
end;
/
exec dbms_stats.flush_database_monitoring_info;
select *
from sys.col_usage$ u
where obj# IN(select object_id 
 from  dba_objects 
 WHERE owner = 'SCOTT'
  AND   object_name = 'T'
 AND   object_Type = 'TABLE')
/
      OBJ#    INTCOL# EQUALITY_PREDS EQUIJOIN_PREDS NONEQUIJOIN_PREDS RANGE_PREDS LIKE_PREDS NULL_PREDS TIMESTAMP
---------- ---------- -------------- -------------- ----------------- ----------- ---------- ---------- ---------
     98167          4              1              0                 0           0          0          0 04-NOV-15

The column usage report tells us that there has been an equality predicate used on the column SKEW.

select dbms_stats.report_col_usage('SCOTT','T') from dual
/
DBMS_STATS.REPORT_COL_USAGE('SCOTT','T')
--------------------------------------------------------------------------------
LEGEND:                                                                                                                                 
.......                                                                                               
                                                
EQ         : Used in single table EQuality predicate
RANGE      : Used in single table RANGE predicate   
LIKE       : Used in single table LIKE predicate    
NULL       : Used in single table is (not) NULL predicate
EQ_JOIN    : Used in EQuality JOIN predicate             
NONEQ_JOIN : Used in NON EQuality JOIN predicate         
FILTER     : Used in single table FILTER predicate       
JOIN       : Used in JOIN predicate                      

DBMS_STATS.REPORT_COL_USAGE('SCOTT','T')                 
-------------------------------------------------------------------------------- 
GROUP_BY   : Used in GROUP BY expression
...............................................................................
###############################################################################
                       COLUMN USAGE REPORT FOR SCOTT.T                                                                       
................................
1. SKEW                                : EQ                                                           
###############################################################################

Now, when I collect statistics with the default METHOD_OPT, I will get a histogram on SKEW,

begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT',tabname=>'T');
end;
/
REM check for histogram - should have gone with no col usage
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from dba_tab_col_statistics
where owner = 'SCOTT'
and  table_name = 'T'
/

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------
T     A            10     0 NONE            1    1000
T     B            10     0 NONE            1    1000
T     C            10     0 NONE            1    1000
T     SKEW        120     0 FREQUENCY     120    1000

Nest, I will delete the column usage and collect the statistics again

REM remove the column usage
exec dbms_stats.reset_col_usage('SCOTT','T');
begin
 dbms_stats.gather_table_stats(ownname=>'SCOTT',tabname=>'T');
end;
/
REM check for histogram - should have gone with no col usage
select table_name, column_name, num_distinct, num_nulls, histogram, num_buckets, sample_size
from dba_tab_col_statistics
where owner = 'SCOTT'
and  table_name = 'T'
/

And now the histogram has gone. QED.

Table Column      Num   Num               Num  Sample
Name  Name   Distinct Nulls Histogram Buckets    Size
----- ------ -------- ----- --------- ------- -------
T     A            10     0 NONE            1    1000
T     B            10     0 NONE            1    1000
T     C            10     0 NONE            1    1000
T     SKEW        120     0 NONE            1    1000

Conclusion

As you add histograms to a table, the time taken to collect statistics and parse statements increases.  I think having a mechanism to remove unwanted histograms is desirable.  However, it has the potential to cause problems, so just be aware of it.
If you are sure that you need histograms on a particular column, then I would suggest creating table preferences for METHOD_OPT and managing those preferences along with the table DDL.

Measuring Tuxedo Queuing in the PeopleSoft Application Server

Why Should I Care About Queuing?

Queuing in the application server is usually an indicator of a performance problem, rather than a problem in its own right.  Requests will back up on the inbound queue because the application server cannot process them as fast as they arrive.  This is usually seen on the APPQ which is serviced by the PSAPPSRV process, but applies to other server processes too.  Common causes include (but are not limited to):

• Poor performance of either SQL on the database or PeopleCode executed within the application server is extending service duration
• The application server domain is undersized for the load.  Increasing the number of application server domains or application server process may be appropriate.  However, before increasing the number of server process it is necessary to ensure that the physical server has sufficient memory and CPU to support the domain (if the application server CPU is overloaded then requests move from the Tuxedo queues to the operating system run queue).
• The application server has too many server processes per queue causing contention in the systems calls that enqueue and dequeue requests to and from IPC queue structure.  A queue with more than 8-10 application server processes can exhibit this contention.  There will be a queue of inbound requests, but not all the server processes will be non-idle.

When user service requests spend time queuing in the application server, that time is part of the users' response time.  Application server queuing is generally to be avoided (although it may be the least worst alternative). 
What you do about queuing depends on the circumstances, but it is something that you do want to know about.

3 Ways to Measure Application Server Queuing

There are several ways to detect queuing in Tuxedo

• Direct measurement of the Tuxedo domain using the tmadmin command-line interface.  A long time ago I wrote a shell script tuxmon.sh.  It periodically runs the printqueue and printserver commands on an application server and extracts comma separated data to a flat that can then be loaded into a database.  It would have to be configured for each domain in a system.
• Direct Measurement with PeopleSoft Performance Monitor (PPM).  Events 301 and 302 simulate the printqueue and printserver commands.  However, event 301 only works from PT8.54 (and at the time of writing I am working on a PT8.53 system).  Even then, the measurements would only be taken once per event cycle, which defaults to every 5 minutes.  I wouldn't recommend increasing the sample frequency, so this will only ever be quite a coarse measurement.
• Indirect Measurement from sampled PPM transactions.  Although includes time spent on the return queue and to unpack the Tuxedo message.  This technique is what the rest of this article is about.

Indirectly Measuring Application Server Queuing from Transactional Data

Every PIA and Portal request includes a Jolt call made by the PeopleSoft servlet to the domain.  The Jolt call is instrumented in PPM as transaction 115.  Various layers in the application server are instrumented in PPM, and the highest point is transaction 400 which where the service enters the PeopleSoft application server code.  Transaction 400 is always the immediate child of transaction 115.  The difference in the duration of these transactions is the duration of the following operations:

• Transmit the message across the network from the web server to the JSH.  There is a persistent TCP socket connection.
• To enqueue the message on the APPQ queue (including writing the message to disk if it cannot fit on the queue).
•  Time spent in the queue
• To dequeue the message from the queue (including reading the message back from disk it was written there).
• To unpack the Tuxedo message and pass the information to the service function
• And then repeat the process for the return message back to the web server via the JSH queue (which is not shown  in tmadmin)

I am going make an assumption that the majority of the time is spent by message waiting in the inbound queue and that time spent on the other activities is negligible.  This is not strictly true, but is good enough for practical purposes.  Any error means that I will tend to overestimate queuing.
Some simple arithmetic can convert this duration into an average queue length. A queue length of n means that n requests are waiting in the queue.  Each second there are n seconds of queue time.  So the number of seconds per second of queue time is the same as the queue length. 
I can take all the sampled transactions in a given time period and aggregate the time spent between transactions 115 and 400.  I must multiply it by the sampling ratio, and then divide it by the duration of the time period for which I am aggregating it.  That gives me the average queue length for that period.
This query aggregates queue time across all application server domains in each system.  It would be easy to examine a specific application server, web server or time period.

REM https://blog.go-faster.co.uk/2015/09/measuring-tuxedo-queuing-in-peoplesoft.html
WITH c AS (
SELECT B.DBNAME, b.pm_sampling_rate
,      TRUNC(c115.pm_agent_Strt_dttm,'mi') pm_agent_dttm
,      A115.PM_DOMAIN_NAME web_domain_name
,      SUBSTR(A400.PM_HOST_PORT,1,INSTR(A400.PM_HOST_PORT,':')-1) PM_tux_HOST
,      SUBSTR(A400.PM_HOST_PORT,INSTR(A400.PM_HOST_PORT,':')+1) PM_tux_PORT
,      A400.PM_DOMAIN_NAME tux_domain_name
,      (C115.pm_trans_duration-C400.pm_trans_duration)/1000 qtime
FROM   PSPMAGENT A115 /*Web server details*/
,      PSPMAGENT A400 /*Application server details*/
,      PSPMSYSDEFN B
,      PSPMTRANSHIST C115 /*Jolt transaction*/
,      PSPMTRANSHIST C400 /*Tuxedo transaction*/
WHERE  A115.PM_SYSTEMID = B.PM_SYSTEMID 
AND    A115.PM_AGENT_INACTIVE = 'N'
AND    C115.PM_AGENTID = A115.PM_AGENTID
AND    C115.PM_TRANS_DEFN_SET=1
AND    C115.PM_TRANS_DEFN_ID=115
AND    C115.pm_trans_status = '1' /*valid transaction only*/
--
AND    A400.PM_SYSTEMID = B.PM_SYSTEMID 
AND    A400.PM_AGENT_INACTIVE = 'N'
AND    C400.PM_AGENTID = A400.PM_AGENTID
AND    C400.PM_TRANS_DEFN_SET=1
AND    C400.PM_TRANS_DEFN_ID=400
AND    C400.pm_trans_status = '1' /*valid transaction only*/
--
AND    C115.PM_INSTANCE_ID = C400.PM_PARENT_INST_ID /*parent-child relationship*/
AND    C115.pm_trans_duration >= C400.pm_trans_duration
), x as (
SELECT dbname, pm_agent_dttm
,      AVG(qtime) avg_qtime
,      MAX(qtime) max_qtime
,      c.pm_sampling_rate*sum(qtime)/60 avg_qlen
,      c.pm_sampling_rate*count(*) num_services
FROM   c
GROUP BY dbname, pm_agent_dttm, pm_sampling_rate
)
SELECT * FROM x
ORDER BY dbname, pm_agent_dttm

• Transactions are aggregated per minute, so the queue time is divided by 60 at the end of the calculation because we are measuring time in seconds.

Then the results from the query can be charted in excel (see http://www2.go-faster.co.uk/scripts.htm#awr_wait.xls). This chart was taken from a real system undergoing a performance load test, and we could see

Is this calculation and assumption reasonable?

The best way to validate this approach would be to measure queuing directly using tmadmin.  I could also try this on a PT8.54 system where event 301 will report the queuing.  This will have to wait for a future opportunity.
However, I can compare queuing with the number of busy application servers at reported by PPM event 302 for the CRM database.  Around 16:28 queuing all but disappears.  We can see that there were a few idle application servers which is consistent with the queue being cleared.  Later the queuing comes back, and most of the application servers are busy again.  So it looks reasonable.

When Is An Idle Wait Not An Idle Wait?

In general, performance tuning is quite straightforward. You work out how much time is spent doing what, and follow the numbers to the things that are taking the most time. If you are fortunate to the have the Diagnostics Pack on Enterprise Edition of Oracle your Active Session History (ASH) will report the active database sessions. If you can measure the overall response time of a batch or application server you have merely to deduct the DB reported in ASH, and the difference is client/middleware time.
While that is an over-simplification, it is substantially true. The rest of this blog is about an exception to the general rule.

A War Story 

I've been working with a system that makes extensive, and probably excessive, use of database links. There is a constellation of 3 Oracle databases and there are database links between them. There is also a soon-to-be legacy DB2 database, and one of the Oracle databases uses Oracle Transparent Gateway to create Heterogeneous Database Links over which the application running on Oracle references data in the DB2 database.
During a load test, nearly all of the 64 application server processes are reported as busy handling requests, yet ASH reports than usually less than 2 database sessions are concurrently busy. You would expect to see 60 application server processes consuming CPU, but CPU does not appear to be as highly utilised as we should expect.

An application SQL trace reports that while the majority of the time is indeed spent on client CPU, about 20% is spent on a few SQL statements that reference synonyms that refer to tables or views in a DB2 database. Why didn't these show up in ASH?

A Simple Test Script 

I wrote a simple test script that just executes the SQL statements that refer to the DB2 objects, but it collects AWR snapshots at the beginning and end of the script, and it also enables Oracle session trace.

set verify on head on timi on feedback on lines 200 trimspool on
spool otg_db2

variable b1 VARCHAR2(10)
variable b2 VARCHAR2(10)

BEGIN
 :b1 := '123456789';
 :b2 := '42';
END;

ALTER SESSION SET tracefile_identifier='OTG_DB2';
ALTER SESSION SET current_schema=APPSCHEMA;

EXEC dbms_workload_repository.create_snapshot;
EXEC dbms_application_info.set_action('OTG_DB2');
EXEC dbms_monitor.session_trace_enable;

SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2
/
SELECT …
FROM db2_object2 a
WHERE a.field1 = :b1 AND a.field2 = :b2
/
…

exec dbms_application_info.set_action('NONE');
exec dbms_monitor.session_Trace_disable;
exec dbms_workload_repository.create_snapshot;

select sample_id, sample_time, sql_id, sql_plan_hash_value, sql_plan_line_id, sql_exec_id, event
from v$active_session_history
where action = 'OTG_DB2';

spool off

The first interesting output is that although some of the queries on DB2 objects took several seconds, I didn't get any rows in the query on ASH buffer for this session.
So, now let's look at the trace file. This is the output for the longest SQL statement having profiled it in TKPROF. We can see that nearly all the time is spent on an event called HS message to agent.

SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.04          0          0          1           0
Fetch        1      0.00       2.73          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       2.77          0          0          1           0

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

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  DFS lock handle                                 1        0.00          0.00
  rdbms ipc reply                                 2        0.00          0.00
  HS message to agent                             5        2.73          2.77
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00

And this is the corresponding section of the raw trace. The execution took just under 42ms, and then the fetch took 2.73 seconds.

PARSING IN CURSOR #4579254328 len=171 dep=0 uid=35 oct=3 lid=0 tim=14984112395546 hv=1291470523 ad='700010b2204a518' sqlid='xxxxxxxxxxxxx'
SELECT …
FROM db2_object1 a
WHERE a.field1 = :b1 AND a.field2 = :b2
END OF STMT
PARSE #4579254328:c=106,e=172,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=14984112395545
WAIT #4579254328: nam='Disk file operations I/O' ela= 23 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=14984112395633
WAIT #4579254328: nam='DFS lock handle' ela= 5205 type|mode=1146617861 id1=3569868743 id2=0 obj#=-1 tim=14984112401137
WAIT #4579254328: nam='rdbms ipc reply' ela= 75 from_process=46 timeout=900 p3=0 obj#=-1 tim=14984112401291
WAIT #4579254328: nam='rdbms ipc reply' ela= 710 from_process=46 timeout=900 p3=0 obj#=-1 tim=14984112402047
WAIT #4579254328: nam='HS message to agent' ela= 3464 p1=0 p2=0 p3=0 obj#=-1 tim=14984112405590
WAIT #4579254328: nam='HS message to agent' ela= 38459 p1=0 p2=0 p3=0 obj#=-1 tim=14984112444724
WAIT #4579254328: nam='HS message to agent' ela= 17 p1=0 p2=0 p3=0 obj#=-1 tim=14984112444791
EXEC #4579254328:c=932,e=49215,p=0,cr=0,cu=1,mis=1,r=0,dep=0,og=1,plh=0,tim=14984112444865
WAIT #4579254328: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=14984112444958
WAIT #4579254328: nam='HS message to agent' ela= 2730045 p1=0 p2=0 p3=0 obj#=-1 tim=14984115175093
WAIT #4579254328: nam='HS message to agent' ela= 8 p1=0 p2=0 p3=0 obj#=-1 tim=14984115175165
FETCH #4579254328:c=206,e=2730295,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=14984115175285
WAIT #4579254328: nam='SQL*Net message from client' ela= 895 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=14984115176264
CLOSE #4579254328:c=10,e=16,dep=0,type=0,tim=14984115176343

Across the whole of my test I have 29 waits on this event totalling 5.3s. Why I am not seeing this event in ASH?

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        9      0.00       0.00          0          0          0           0
Execute     10      0.00       0.21          0          0          1           3
Fetch        7      0.00       5.10          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       26      0.01       5.32          0          0          1           3

Misses in library cache during parse: 3
Misses in library cache during execute: 4

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       9        0.00          0.00
  SQL*Net message from client                     9        0.00          0.00
  Disk file operations I/O                        9        0.00          0.00
  DFS lock handle                                 1        0.00          0.00
  rdbms ipc reply                                 2        0.00          0.00
  HS message to agent                            29        2.73          5.30
  library cache pin                               2        0.00          0.00

If I generate an ASH report on the two snapshots created in this test and look at the Foreground events I might start to see why. AWR reports 29 waits totalling 5 seconds, so that agrees. However, note that this is at the bottom of the report with 'SQL*Net message from client' and there is no '%DB Time'.

We (should) know that 'SQL*Net message from client' is an idle event. So we can understand that there are 806 seconds reported on this event in this AWR report because there were 151 sessions connect to the database, most of which were mostly idle for the 6 seconds between the AWR snapshots. That is perfectly normal.
However, HS message to agent is classed as an idle wait, although the user was not idle. During this event the application is not busy, it is waiting for the Oracle database to respond, which is, in turn, waiting for the remote non-Oracle database to respond.
 This is in contrast to Oracle-to-Oracle (homogeneous) database links which report time to 'SQL*Net message from dblink' which is not an idle wait, but part of the 'Network' wait class. I think the difference is an anomaly.
The next question is how much time my application spent on this event. For that I must look at the AWR data, either by generating an AWR report that corresponds to the load test, or directly in dba_hist_system_event.

Conclusion

1. I am not the first person to call this out, just the latest person to get caught by it. It may be an idle wait, but the user is waiting for the database to respond. 

   Database Link	Wait Event	Wait Class
   Heterogeneous	HS message to agent	Idle
   Homogeneous	SQL*Net message from dblink	Network

2. I got as far as starting to write an e-mail to a colleague asking for help, but before sending it I realised that I could do more to find out what was happening. Perhaps just the act of trying to explain the problem helped me to think more clearly about it.

PeopleTools 8.54: Performance Performance Monitor Enhancements

This is part of a series of articles about new features and differences in PeopleTools 8.54 that will be of interest to the Oracle DBA.

Transaction History Search Component

There are a number of changes:

• You can specify multiple system identifiers.  For example, you might be monitoring Portal, HR and CRM.  Now you can search across all of them in a single search.
• It has always been the case that when you drill into the Performance Monitoring Unit (PMU), by clicking on the tree icon, you would see the whole of a PMU that invoked services from different systems.
• You can also specify multiple transaction types, rather than have to search each transaction type individually.

This is a useful enhancement when searching for a specific or a small number of transaction.  However, I do not think it will save you from having to query the underlying transactions table.

PPM Archive Process

The PPM archive process (PSPM_ARCHIVE) has been significantly rewritten in PeopleTools 8.54.  In many places, it still uses this expression to identify rows to be archived or purged:

%DateTimeDiff(X.PM_MON_STRT_DTTM, %CurrentDateTimeIn) >= (PM_MAX_HIST_AGE * 24 * 60)

This expands to

ROUND((CAST(( CAST(SYSTIMESTAMP AS TIMESTAMP)) AS DATE) - CAST((X.PM_MON_STRT_DTTM) AS DATE)) * 1440, 0)
   >= (PM_MAX_HIST_AGE * 24 *  60)

which has no chance of using an index.  This used to cause performance problems when the archive process had not been run for a while and the high water marks on the history tables had built up.

Now, the archive process now works hour by hour, and this will use the index on the timestamp column.

"… AND X.PM_MON_STRT_DTTM <= SYSDATE - PM_MAX_HIST_AGE 
and (PM_MON_STRT_DTTM) >= %Datetimein('" | DateTimeValue(&StTime) | "')
and (PM_MON_STRT_DTTM) <= %DateTimeIn('" | DateTimeValue(&EndTime) | "')"

Tuxedo Queuing

Since Performance Monitor was first introduced, event 301 has never reported the length of the inbound message queues in Tuxedo.  The reported queue length was always zero.  This may have been fixed in PeopleTools 8.53, but I have only just noticed it

Java Management Extensions (JMX) Support

There have been some additions to Performance Monitor that suggest that it will be possible to extract performance metrics using JMX.  The implication is that the Oracle Enterprise Manager Application Management Pack of PeopleSoft will be able to do this.  However, so far I haven't found any documentation. The new component is not mentioned in the PeopleTools 8.54: Performance Monitor documentation.

• New Table
• PS_PTPMJMXUSER - keyed on PM_AGENTID
• New Columns
• PSPMSYSDEFAULTS - PTPHONYKEY.  So far I have only seen it set to 0.
• PSPMAGENT - PM_JMX_RMI_PORT.  So far only seen it set to 1
• New Component