Posts Tagged ‘parallel slaves’
Automating tkprof on parallel slaves
One thing very disappointing on parallel execution is the fact that the trace files of slave sessions are scattered as different files in the background dump directory.
So I built up my own script which automates the execution of tkprof on those scattered trace files.
1. pq_trace.sql generates the series of tkprof command with the input of coordinate session id.
set heading off set timing off set feedback off set verify off set serveroutput on size 100000 spool generate_pq_tkprof.sql define __QCID = &1 declare v_dir varchar2(4000); v_inst varchar2(4000); v_trcfile varchar2(4000); v_cmd varchar2(4000); begin -- get dump directory for v in (select banner from v$version where rownum = 1) loop select value into v_dir from v$parameter where name = 'background_dump_dest'; end loop; -- get instance name select value into v_inst from v$parameter where name = 'instance_name'; -- generate series of tkprof command for s in (select s.sid, p.spid, rownum-1 as server# from v$px_session s, v$px_process p where s.sid = p.sid and s.qcsid in (&__QCID) and s.sid <> s.qcsid) loop v_trcfile := v_dir||'\'||v_inst||'_'||'p'||lpad(to_char(s.server#),3,'0')|| '_'||s.spid||'.trc'; v_cmd := 'ho tkprof ' || v_trcfile || ' trc' || '_' || s.server# || '.out'; dbms_output.put_line(v_cmd); end loop; end; / spool off set heading on set timing on set feedback on set verify on set serveroutput off ed generate_pq_tkprof
2. The output of pq_trace.sql script is stored as generate_pq_tkprof.sql as following:
ed generate_pq_tkprof.sql ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p000_2792.trc trc_0.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p001_704.trc trc_1.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p002_4892.trc trc_2.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p003_2728.trc trc_3.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p004_1244.trc trc_4.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p005_2736.trc trc_5.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p006_4508.trc trc_6.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p007_2432.trc trc_7.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p008_3916.trc trc_8.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p009_656.trc trc_9.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p010_5308.trc trc_10.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p011_4880.trc trc_11.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p012_4288.trc trc_12.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p013_4528.trc trc_13.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p014_5852.trc trc_14.out ho tkprof C:\ORACLE\ADMIN\UKJA10\BDUMP\ukja10_p015_2716.trc trc_15.out
3. Following is a simple demonstration.
# Session A (session id = 130)
alter session set tracefile_identifier = &1; @trace_on 10046 8 select /*+ parallel(t1 8) */ count(*) from t1, t1 where rownum <= 500000 ; @trace_off
# Session B
While session A executes parallel query
@pq_trace 130 -- 130 is id of session A
After the parallel query of session A completes.
UKJA@ukja102> @generate_pq_tkprof TKPROF: Release 11.1.0.6.0 - Production on Thu Mar 12 16:41:06 2009 Copyright (c) 1982, 2007, Oracle. All rights reserved. ...
UKJA@ukja102> ed trc_5.out select /*+ parallel(t1 8) */ count(*) from t1, t1 where rownum <= 500000 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 14.18 58.32 0 16 0 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 14.18 58.32 0 16 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 SORT AGGREGATE (cr=0 pr=0 pw=0 time=0 us) 0 COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us) 0 PX COORDINATOR (cr=0 pr=0 pw=0 time=0 us) 0 PX SEND QC (RANDOM) :TQ10001 (cr=0 pr=0 pw=0 time=0 us) 500000 COUNT STOPKEY (cr=16 pr=0 pw=0 time=52514746 us) 500000 MERGE JOIN CARTESIAN (cr=16 pr=0 pw=0 time=32514719 us) 345 SORT JOIN (cr=0 pr=0 pw=0 time=894433 us) 10000 PX RECEIVE (cr=0 pr=0 pw=0 time=701281 us) 0 PX SEND BROADCAST :TQ10000 (cr=0 pr=0 pw=0 time=0 us) 0 PX BLOCK ITERATOR (cr=0 pr=0 pw=0 time=0 us) 0 TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us) 500000 BUFFER SORT (cr=16 pr=0 pw=0 time=13119697 us) 1452 PX BLOCK ITERATOR (cr=16 pr=0 pw=0 time=118476 us) 1452 TABLE ACCESS FULL T1 (cr=16 pr=0 pw=0 time=53795 us) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ PX Deq: Execution Msg 6 0.05 0.09 PX Deq: Table Q Normal 3 0.09 0.09 PX Deq Credit: send blkd 2 0.00 0.00 PX qref latch 2 0.00 0.00
These kinds of automation techniques are really time and even life savers. :)