AWK to the rescue 2 – 10046+10053 = ?

I’ve created recently a script in AWK to create wait event histogram from 10046 trace file. The script can be found here.

I thought that a good idea would be creating a little script to analyze the contents of 10053 and 10046 events together. So I wrote one 🙂

You can download it here: http://ora-600.pl/oinstall/format_10046_10053.awk

How it works? Well let’s assume that I want to analyze a few queries – check wait events, display final query after transformation and explain plan for each individual query.

It might look like this:

SQL> select value from v$diag_info where name='Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_19929.trc

SQL> select e.first_name, e.last_name
  2  from employees e, departments d
  3  where e.department_id=d.department_id
  4  and   e.salary<1000;

no rows selected

SQL> ed
Wrote file afiedt.buf

  1  select p.prod_category, sum(s.amount_sold) as sld
  2  from sh.sales2 s, sh.products p
  3  where s.prod_id=p.prod_id
  4  group by p.prod_category
  5* having sum(s.amount_sold)<=10
SQL>
SQL> /

no rows selected

Now we can use my AWK script to analyze the combined 10046 and 10053 trace files.

[oracle@rico ~]$ awk -f format_10046_10053.awk /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_19929.trc

ORIGINAL SQL:
select e.first_name, e.last_name
from employees e, departments d
where e.department_id=d.department_id
and   e.salary<1000
*******************************************
sql_id=2q0ks31jykxn9
SELECT "E"."FIRST_NAME" "FIRST_NAME"
	,"E"."LAST_NAME" "LAST_NAME"
	FROM "HR"."EMPLOYEES" "E"
		WHERE "E"."DEPARTMENT_ID" IS NOT NULL
		 AND "E"."SALARY"<1000
		 AND 0<1000

----- Plan Table -----

============
Plan Table
============
--------------------------------------+-----------------------------------+
| Id  | Operation          | Name     | Rows  | Bytes | Cost  | Time      |
--------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT   |          |       |       |     3 |           |
| 1   |  TABLE ACCESS FULL | EMPLOYEES|     1 |    22 |     3 |  00:00:01 |
--------------------------------------+-----------------------------------+
Predicate Information:
----------------------
1 - filter(("E"."SALARY"<1000 AND "E"."DEPARTMENT_ID" IS NOT NULL))

Content of other_xml column
===========================
  derived_cpu_dop: 1
  derived_io_dop : 2
  dop_reason     : parallel threshold
  dop            : 1
  px_in_memory_imc: no
  px_in_memory   : no
  db_version     : 12.1.0.2
  parse_schema   : HR
  plan_hash_full : 3476115102
  plan_hash      : 1445457117
  plan_hash_2    : 3476115102
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')
      DB_VERSION('12.1.0.2')
      ALL_ROWS
      NO_PARALLEL
      OUTLINE_LEAF(@"SEL$F7859CDE")
      ELIMINATE_JOIN(@"SEL$1" "D"@"SEL$1")
      OUTLINE(@"SEL$1")
      FULL(@"SEL$F7859CDE" "E"@"SEL$1")
    END_OUTLINE_DATA
  */

db file scattered read elapsed time (us): 920

obj#=92593 elapsed time (us): 920

ORIGINAL SQL:
select p.prod_category, sum(s.amount_sold) as sld
from sh.sales2 s, sh.products p
where s.prod_id=p.prod_id
group by p.prod_category
having sum(s.amount_sold)<=10
*******************************************
sql_id=09w820zyynx4t
SELECT "P"."PROD_CATEGORY" "PROD_CATEGORY"
	,SUM("S"."AMOUNT_SOLD") "SLD"
	FROM "SH"."SALES2" "S"
	,"SH"."PRODUCTS" "P"
		WHERE "S"."PROD_ID"="P"."PROD_ID"
		GROUP BY "P"."PROD_CATEGORY"
		HAVING SUM("S"."AMOUNT_SOLD")<=10

----- Plan Table -----

============
Plan Table
============
---------------------------------------------------------+-----------------------------------+
| Id  | Operation                  | Name                | Rows  | Bytes | Cost  | Time      |
---------------------------------------------------------+-----------------------------------+
| 0   | SELECT STATEMENT           |                     |       |       |   13K |           |
| 1   |  FILTER                    |                     |       |       |       |           |
| 2   |   HASH GROUP BY            |                     |     1 |    30 |   13K |  00:00:28 |
| 3   |    HASH JOIN               |                     | 9870K |  289M |   13K |  00:00:27 |
| 4   |     VIEW                   | index$_join$_002    |    72 |  1512 |     0 |           |
| 5   |      HASH JOIN             |                     |       |       |       |           |
| 6   |       INDEX FAST FULL SCAN | PRODUCTS_PK         |    72 |  1512 |     0 |           |
| 7   |       INDEX FAST FULL SCAN | PRODUCTS_PROD_CAT_IX|    72 |  1512 |     0 |           |
| 8   |     TABLE ACCESS FULL      | SALES2              | 9870K |   87M |   13K |  00:00:27 |
---------------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
1 - filter(SUM("S"."AMOUNT_SOLD")<=10)
3 - access("S"."PROD_ID"="P"."PROD_ID")
5 - access(ROWID=ROWID)

Content of other_xml column
===========================
  derived_cpu_dop: 1
  derived_io_dop : 2
  dop_reason     : parallel threshold
  dop            : 1
  px_in_memory_imc: no
  px_in_memory   : no
  db_version     : 12.1.0.2
  parse_schema   : HR
  plan_hash_full : 3733219923
  plan_hash      : 2523389659
  plan_hash_2    : 3733219923
  Outline Data:
  /*+
    BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')
      DB_VERSION('12.1.0.2')
      ALL_ROWS
      NO_PARALLEL
      OUTLINE_LEAF(@"SEL$FD64DD72")
      OUTLINE_LEAF(@"SEL$1")
      INDEX_JOIN(@"SEL$1" "P"@"SEL$1" ("PRODUCTS"."PROD_ID") ("PRODUCTS"."PROD_CATEGORY"))
      FULL(@"SEL$1" "S"@"SEL$1")
      LEADING(@"SEL$1" "P"@"SEL$1" "S"@"SEL$1")
      USE_HASH(@"SEL$1" "S"@"SEL$1")
      USE_HASH_AGGREGATION(@"SEL$1")
    END_OUTLINE_DATA
  */

db file scattered read<= 1(ms)		17	0.0426065
db file scattered read<= 4(ms)		163	0.408521
db file scattered read<= 8(ms)		218	0.546366
db file scattered read<=16(ms)		1	0.00250627

db file scattered read elapsed time (us): 1701645
db file sequential read elapsed time (us): 2721
Disk file operations I/O elapsed time (us): 41

obj#=93261 elapsed time (us): 1702108
obj#=92744 elapsed time (us): 1161
obj#=92749 elapsed time (us): 1138

The output shows original SQL text for each SQL_ID found in the trace file, SQL text after transformations – formatted a little bit for easy reading – then we can see plan table output with additional data, wait event histogram, total wait event times and total time waited for object id found in the trace file.

I think it may be useful in some cases.

Notice the version of AWK, which I’m using – 4.1.3. This is important for feature PROCINFO["sorted_in"] which I have used to sort arrays descending by values – it’s available from AWK v4 – in earlier versions it doesn’t work. You can find the newest versions here: http://ftp.gnu.org/gnu/gawk/?C=M;O=D

It’s a fresh version of this script so you should test it. Either way – AWK rocks!