Tweaked script to show top SQL by force matching signature

I just finished another production tuning exercise that is like two recent posts:

Two New ASH FORCE_MATCHING_SIGNATURE scripts

Tuning Example With Outline Hints and SQL Profile

The biggest new thing was that I ran the ashtopelapsed.sql script that I mentioned in the first post above but it missed the top SQL statement for the job I was trying to tune. I am struggling to get the logic right. I am trying to write an ASH-based top SQL report for a given time range. It is like an AWR report where you see the top elapsed time SQL statement for the given time frame. But I am grouping by FORCE_MATCHING_SIGNATURE and not SQL_ID because I want to see the top SQL that all have the same signature but different SQL_IDs. In this case there was a PeopleSoft update and select statement that did not use bind variables, so each execution had its own SQL_ID. Here is the select:

SELECT 
DISTINCT TO_CHAR(A.ACCOUNTING_DT,'YYYY-MM-DD') 
FROM PS_HR_ACCTG_LINE A 
WHERE 
A.APPL_JRNL_ID = 'ABCDE' AND 
A.BUSINESS_UNIT_GL = 'FG' AND 
(A.LEDGER_GROUP = ' ' OR A.LEDGER_GROUP = 'HIJK') AND 
A.GL_DISTRIB_STATUS = 'N' AND 
A.ACCOUNTING_DT >= TO_DATE('2006-09-03','YYYY-MM-DD') AND 
A.ACCOUNTING_DT <= TO_DATE('2021-09-04','YYYY-MM-DD');

I guess this runs for different values of BUSINESS_UNIT_GL, ACCOUNTING_DT, etc.

I am trying to get ashtopelapsed.sql to show the top SQL by force matching signature:

create table topsigs as
select 
FORCE_MATCHING_SIGNATURE,
count(*) active
from DBA_HIST_ACTIVE_SESS_HISTORY a
where 
sample_time 
between 
to_date('13-SEP-2021 01:00:19','DD-MON-YYYY HH24:MI:SS')
and 
to_date('13-SEP-2021 06:52:25','DD-MON-YYYY HH24:MI:SS')
group by
FORCE_MATCHING_SIGNATURE;

In this case during the time frame of the problem job, from about 1 to 7 am yesterday.

But then I want to find at least one SQL_ID for the given value of FORCE_MATCHING_SIGNATURE so I can then get its text as an example of a real SQL statement that has the signature:

create table sigtoid as
select 
t.FORCE_MATCHING_SIGNATURE,
min(a.sql_id) a_sql_id
from
topsigs t,
DBA_HIST_ACTIVE_SESS_HISTORY a,
DBA_HIST_SQLTEXT s
where
t.FORCE_MATCHING_SIGNATURE = a.FORCE_MATCHING_SIGNATURE and
a.sql_id = s.sql_id
group by t.FORCE_MATCHING_SIGNATURE;

There has to be a row in DBA_HIST_SQLTEXT for the signature or else I will not have an example SQL statement and the signature will get dropped from the report. I may need to put some sort of outer join somewhere so I can see the FORCE_MATCHING_SIGNATURE values that do not have an example SQL_ID in DBA_HIST_SQLTEXT. But fortunately, with the last revision (commit) to ashtopelapsed.sql I was able to see the text of an example SQL statement for each of the top signatures during the time when the problem job ran.

The other funny thing is that I forgot I had ashfmscount.sql so I ended up rewriting it. I need to read my own blog posts. 🙂 Hopefully this more detailed post will serve as a model for future performance tuning efforts and so I will not forget the scripts that I used this time.

As for hacking a SQL Profile together, the subject of the second post above, I edited one in vi as described in the post and the other I just extracted using coe_xfr_sql_profile.sql. I also edited both SQL Profiles to use FORCE = TRUE to make the SQL profile apply to all SQL statements with the same signature. I described FORCE = TRUE in earlier posts:

force_match => TRUE option of DBMS_SQLTUNE.IMPORT_SQL_PROFILE

Example of coe_xfr_sql_profile force_match TRUE

I think there is some overlap in all these posts, but I wanted to document today’s tuning exercise. The biggest new thing is the improvement of ashtopelapsed.sql.

Couple of images of the AWR and ASH top SQL for the time of this long running job:

AWR
ASH

Neither of these captured the top SQL by signature so that is why ashtopelapsed.sql was helpful. There may be some Oracle supplied way to do the same thing that I do not know about but the standard awrrpt.sql and ashrpt.sql do not handle this situation well. I could not find any useful information about my long running job in the top SQL portions of the AWR and ASH reports.

Here is the top output from ashtopelapsed.sql:

    ACTIVE FORCE_MATCHING_SIGNATURE EXAMPLE_SQL_I SQL_TEXT
---------- ------------------------ ------------- --------------------------
     10389                        0 02101wfuxvwtd INSERT INTO PS_AERUNCONTRO
      1394      2407690495325880429 003t0wk45taqs UPDATE PS_HR_ACCTG_LINE SE
       858      9373188292577351646 04hvza4k3u72x INSERT INTO PS_PROJ_RES_TM
                                                  ID, VOUCHER_ID, VOUCHER_LI
                                                  D_DETAIL, CST_DISTRIB_STAT
                                                  _TYPE, JL.RESOURCE_TYPE, J
                                                  JRNL_HEADER JH , PS_JRNL_L

       718       810675553005238195 b8fakhtc5g3rx select * from (select a.os
       646     12856152818202055532 00mmbs0c6bh1a SELECT DISTINCT TO_CHAR(A.

I created FORCE=TRUE SQL Profiles for FORCE_MATCHING_SIGNATURE values 2407690495325880429 and 12856152818202055532. Here was the output from ashfmscount.sql:

FORCE_MATCHING_SIGNATURE     ACTIVE
------------------------ ----------
     2407690495325880429       1394
    12856152818202055532        646
    12319028094632613940         43
    12084330158653099691          2
    10829167302201730459          2
     4612906341224490548          1

Almost all the 6-hour runtime was taken up by 2407690495325880429 and 12856152818202055532. The units are in 10 seconds so in hours it is:

((1394 + 646)*10)/3600.0 = 5.666666666666667

Almost all the job run time was spent on SQL statements that match these two signatures.

These two had full scans and needed index skip scans.

Bad plan:

Plan hash value: 3305693634
-----------------------------------------------
| Id  | Operation          | Name             |
-----------------------------------------------
|   0 | UPDATE STATEMENT   |                  |
|   1 |  UPDATE            | PS_HR_ACCTG_LINE |
|   2 |   TABLE ACCESS FULL| PS_HR_ACCTG_LINE |
-----------------------------------------------

Good plan:

Plan hash value: 1538925713
---------------------------------------------------------
| Id  | Operation                    | Name             |
---------------------------------------------------------
|   0 | UPDATE STATEMENT             |                  |
|   1 |  UPDATE                      | PS_HR_ACCTG_LINE |
|*  2 |   TABLE ACCESS BY INDEX ROWID| PS_HR_ACCTG_LINE |
|*  3 |    INDEX SKIP SCAN           | PSAHR_ACCTG_LINE |
---------------------------------------------------------

Not to beat a dead horse, but my main point is that I updated ashtopelapsed.sql to be useful in this situation. It gave me information that the AWR and ASH reports did not.

Here are the scripts that I used for this tuning example:

ashdump.sql – dump out a single 10 second point in time to find the session that is running the batch job

I also had to run this script which is not in my git repository (it is based on ashcount.sql which is my generic script for grouping by certain ash columns).

     select
  2  SESSION_ID,count(*) active
  3  from DBA_HIST_ACTIVE_SESS_HISTORY a
  4  where
  5  sample_time
  6  between
  7  to_date('13-SEP-2021 01:00:19','DD-MON-YYYY HH24:MI:SS')
  8  and
  9  to_date('13-SEP-2021 06:52:25','DD-MON-YYYY HH24:MI:SS')
 10  and program like 'PSAESRV%'
 11  group by SESSION_ID
 12  order by active desc;

SESSION_ID     ACTIVE
---------- ----------
      1039       2088
      1005        957
       858        804
      1006        195
       993        150
       942        143
      1060        114
       940        109
       927         69
      1026          1

I was trying to figure out which PSAESRV session was the one that ran all 6 hours. Session 1039 was the one, so I used it in ashfmscount.sql.

ashfmscount.sql – find the top signatures for the session that is the batch job

ashtopelapsed.sql – get the text of the top SQL statements grouped by signature in the time frame that the job ran

plan.sql – get a plan and output an outline hint to match it

test2.sql – test query with and without outline hint. also get plan hash value in memory so it can be extracted by sqlt.

optimizerstatistics – get index columns and column statistics

fmsstat2.sql – show execution history of 2407690495325880429 from AWR – here is before the profile:

FORCE_MATCHING_SIGNATURE SQL_ID        PLAN_HASH_VALUE END_INTERVAL_TIME        
------------------------ ------------- --------------- -------------------------
     2407690495325880429 03jh5xnnsts7q      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 17wshhdq89azx      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 1k4a28bdg7r8h      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 3zhumhfujfwj5      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 59xs2q8215bby      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 666s10cy2k3fh      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 6bdybc28zn3fg      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 7050x70hjg5mj      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 7wvsquchacp2p      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 8yjhydta27wsn      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 ahj6g61c8hzcq      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 ba76xa0dpua3n      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 bfzkxy486cfu5      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 cg65kxmcytw00      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 d63wz9wyhp10y      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 dk7annutx6n4z      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 dpw0m2t5dmcs8      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 fx4q3cpn84zbf      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 gbc4ksykvucqk      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 gn81xu18vsctn      3305693634 06-AUG-21 02.00.46.749 AM
     2407690495325880429 gxvwq870b82tg      3305693634 06-AUG-21 02.00.46.749 AM


vsqlarea.sql – show current execution details such as plan for 2407690495325880429 after the profile

LAST_ACTIVE         FORCE_MATCHING_SIGNATURE SQL_ID        PLAN_HASH_VALUE
------------------- ------------------------ ------------- ---------------
2021-09-14 17:54:36      2407690495325880429 5vczbrua1hnyk      1538925713
2021-09-14 17:54:36      2407690495325880429 gb7awt1g0spj3      1538925713
2021-09-14 17:54:34      2407690495325880429 54tz4ks94ard2      1538925713
2021-09-14 17:49:13      2407690495325880429 g9r370krad681      1538925713
2021-09-14 17:49:12      2407690495325880429 g4mqhstqmb616      1538925713
2021-09-14 17:43:19      2407690495325880429 apfc4uuksxzt2      1538925713
2021-09-14 17:43:18      2407690495325880429 g1k89u3xqb0nt      1538925713
2021-09-14 17:43:17      2407690495325880429 1rshyrb28xppz      1538925713
2021-09-14 17:36:52      2407690495325880429 934a88k6ct5ct      1538925713

The job ran last night in about 36 minutes instead of almost 6 hours, so it was a big improvement.

I was not able to improve the performance of this long running job using AWR or ASH reports but once I fixed an issue with my ashtopelapsed.sql script and used it along with my other ASH and non-ASH scripts I was able to resolve the performance issue. The job had many update and select statements that were too short to show up on the AWR and ASH reports but when summarized by their force matching signatures they showed up at the top of my ashtopelapsed.sql and ashfmscount.sql scripts’ outputs. Going forward I hope to use the collection of scripts described in this post when faced with tuning situations where an AWR report does not point to a top SQL statement. I may start using these on a regular basis even in cases where the AWR report does provide helpful information just to have another source of information.

Bobby

About Bobby

I live in Chandler, Arizona with my wife and three daughters. I work for US Foods, the second largest food distribution company in the United States. I have worked in the Information Technology field since 1989. I have a passion for Oracle database performance tuning because I enjoy challenging technical problems that require an understanding of computer science. I enjoy communicating with people about my work.
This entry was posted in Uncategorized. Bookmark the permalink.

2 Responses to Tweaked script to show top SQL by force matching signature

  1. Anonymous says:

    Hello!

    Nice post! Thank you.
    This database improvement idea might be interesting for you reading this article.
    https://community.oracle.com/tech/apps-infra/discussion/4397565/awr-enhancement-new-unbound-sql-statistics-section-making-dark-matter-visible#latest

    If it gets enough votes it may even be implemented by Oracle. Check it out.
    Cheers,
    RobK

    • Bobby says:

      Nice post. I think it would be great to add something like that to an AWR report. I think that other databases have something like that. I have spent a little time looking at MySQL recently and I think MySQL has digests that are the SQL without the constants. I am not sure if Oracle has a way to display the SQL in that form but it must do something internally to get the force matching signatures.

      Thank you for commenting on my blog post.

      Bobby

Leave a Reply

Your email address will not be published.

This site uses Akismet to reduce spam. Learn how your comment data is processed.