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:
1 | SQL> select value from v$diag_info where name='Default Trace File'; |
4 | -------------------------------------------------------------------------------- |
5 | /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_19929.trc |
7 | SQL> select e.first_name, e.last_name |
8 | 2 from employees e, departments d |
9 | 3 where e.department_id=d.department_id |
17 | 1 select p.prod_category, sum(s.amount_sold) as sld |
18 | 2 from sh.sales2 s, sh.products p |
19 | 3 where s.prod_id=p.prod_id |
20 | 4 group by p.prod_category |
21 | 5* having sum(s.amount_sold)<=10 |
Now we can use my AWK script to analyze the combined 10046 and 10053 trace files.
1 | [oracle@rico ~]$ awk -f format_10046_10053.awk /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_19929.trc |
4 | select e.first_name, e.last_name |
5 | from employees e, departments d |
6 | where e.department_id=d.department_id |
8 | ******************************************* |
10 | SELECT "E"."FIRST_NAME" "FIRST_NAME" |
11 | ,"E"."LAST_NAME" "LAST_NAME" |
12 | FROM "HR"."EMPLOYEES" "E" |
13 | WHERE "E"."DEPARTMENT_ID" IS NOT NULL |
22 | --------------------------------------+-----------------------------------+ |
23 | | Id | Operation | Name | Rows | Bytes | Cost | Time | |
24 | --------------------------------------+-----------------------------------+ |
25 | | 0 | SELECT STATEMENT | | | | 3 | | |
26 | | 1 | TABLE ACCESS FULL | EMPLOYEES| 1 | 22 | 3 | 00:00:01 | |
27 | --------------------------------------+-----------------------------------+ |
30 | 1 - filter(("E"."SALARY"<1000 AND "E"."DEPARTMENT_ID" IS NOT NULL)) |
32 | Content of other_xml column |
33 | =========================== |
36 | dop_reason : parallel threshold |
42 | plan_hash_full : 3476115102 |
43 | plan_hash : 1445457117 |
44 | plan_hash_2 : 3476115102 |
48 | IGNORE_OPTIM_EMBEDDED_HINTS |
49 | OPTIMIZER_FEATURES_ENABLE('12.1.0.2') |
50 | DB_VERSION('12.1.0.2') |
53 | OUTLINE_LEAF(@"SEL$F7859CDE") |
54 | ELIMINATE_JOIN(@"SEL$1" "D"@"SEL$1") |
56 | FULL(@"SEL$F7859CDE" "E"@"SEL$1") |
60 | db file scattered read elapsed time (us): 920 |
62 | obj#=92593 elapsed time (us): 920 |
65 | select p.prod_category, sum(s.amount_sold) as sld |
66 | from sh.sales2 s, sh.products p |
67 | where s.prod_id=p.prod_id |
68 | group by p.prod_category |
69 | having sum(s.amount_sold)<=10 |
70 | ******************************************* |
72 | SELECT "P"."PROD_CATEGORY" "PROD_CATEGORY" |
73 | ,SUM("S"."AMOUNT_SOLD") "SLD" |
74 | FROM "SH"."SALES2" "S" |
76 | WHERE "S"."PROD_ID"="P"."PROD_ID" |
77 | GROUP BY "P"."PROD_CATEGORY" |
78 | HAVING SUM("S"."AMOUNT_SOLD")<=10 |
85 | ---------------------------------------------------------+-----------------------------------+ |
86 | | Id | Operation | Name | Rows | Bytes | Cost | Time | |
87 | ---------------------------------------------------------+-----------------------------------+ |
88 | | 0 | SELECT STATEMENT | | | | 13K | | |
89 | | 1 | FILTER | | | | | | |
90 | | 2 | HASH GROUP BY | | 1 | 30 | 13K | 00:00:28 | |
91 | | 3 | HASH JOIN | | 9870K | 289M | 13K | 00:00:27 | |
92 | | 4 | VIEW | index$_join$_002 | 72 | 1512 | 0 | | |
93 | | 5 | HASH JOIN | | | | | | |
94 | | 6 | INDEX FAST FULL SCAN | PRODUCTS_PK | 72 | 1512 | 0 | | |
95 | | 7 | INDEX FAST FULL SCAN | PRODUCTS_PROD_CAT_IX| 72 | 1512 | 0 | | |
96 | | 8 | TABLE ACCESS FULL | SALES2 | 9870K | 87M | 13K | 00:00:27 | |
97 | ---------------------------------------------------------+-----------------------------------+ |
100 | 1 - filter(SUM("S"."AMOUNT_SOLD")<=10) |
101 | 3 - access("S"."PROD_ID"="P"."PROD_ID") |
102 | 5 - access(ROWID=ROWID) |
104 | Content of other_xml column |
105 | =========================== |
108 | dop_reason : parallel threshold |
112 | db_version : 12.1.0.2 |
114 | plan_hash_full : 3733219923 |
115 | plan_hash : 2523389659 |
116 | plan_hash_2 : 3733219923 |
120 | IGNORE_OPTIM_EMBEDDED_HINTS |
121 | OPTIMIZER_FEATURES_ENABLE('12.1.0.2') |
122 | DB_VERSION('12.1.0.2') |
125 | OUTLINE_LEAF(@"SEL$FD64DD72") |
126 | OUTLINE_LEAF(@"SEL$1") |
127 | INDEX_JOIN(@"SEL$1" "P"@"SEL$1" ("PRODUCTS"."PROD_ID") ("PRODUCTS"."PROD_CATEGORY")) |
128 | FULL(@"SEL$1" "S"@"SEL$1") |
129 | LEADING(@"SEL$1" "P"@"SEL$1" "S"@"SEL$1") |
130 | USE_HASH(@"SEL$1" "S"@"SEL$1") |
131 | USE_HASH_AGGREGATION(@"SEL$1") |
135 | db file scattered read<= 1(ms) 17 0.0426065 |
136 | db file scattered read<= 4(ms) 163 0.408521 |
137 | db file scattered read<= 8(ms) 218 0.546366 |
138 | db file scattered read<=16(ms) 1 0.00250627 |
140 | db file scattered read elapsed time (us): 1701645 |
141 | db file sequential read elapsed time (us): 2721 |
142 | Disk file operations I/O elapsed time (us): 41 |
144 | obj#=93261 elapsed time (us): 1702108 |
145 | obj#=92744 elapsed time (us): 1161 |
146 | 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!
