Hi, recently I copied a production database X to a remote location, to serve as a test upgrade database. Original is 32 bit and test database is 64 bit. After migration it turned out that one sql statement consumed much more CPU during EXECUTE phase than on production database. Explain plans are the same. Why CPU is different? How can I trace the problem?
ORIGINAL SERVER TKPROF OUTPUT:
call count cpu elapsed disk query current rows
Parse 1 0.12 0.33 0 0 2 0
Execute 1 542.60 2165.29 2 6 0 0
Fetch 0 0.00 0.00 0 0 0 0
total 2 542.73 2165.62 2 6 2 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 66 (SPB)
Rows Row Source Operation
0 SORT UNIQUE (cr=6 pr=2 pw=0 time=719909655 us)
0 FILTER (cr=6 pr=2 pw=0 time=719909615 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=719895787 us)
2 HASH JOIN (cr=0 pr=0 pw=0 time=719881575 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=1210563833 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=1210549798 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=1210519159 us)
330261 REMOTE TWFLPROCESSINSTANCES (cr=0 pr=0 pw=0 time=29176788 us)
2 REMOTE TAMCONTRACTEDITEMD (cr=0 pr=0 pw=0 time=1177866001 us)
2 REMOTE TAMPROPVALUES (cr=0 pr=0 pw=0 time=30580 us)
2 REMOTE TREPVALUELISTITEMS (cr=0 pr=0 pw=0 time=13973 us)
24542745 REMOTE TAMCONTRACTEDITEMD (cr=0 pr=0 pw=0 time=638116004 us)
2 REMOTE TWFLPROCESSINSTANCES (cr=0 pr=0 pw=0 time=14154 us)
2 INDEX RANGE SCAN IDX_PROCES_ID (cr=6 pr=2 pw=0 time=13706 us)(object id 546934)
Rows Execution Plan
0 INSERT STATEMENT MODE: ALL_ROWS
0 SORT (UNIQUE)
0 FILTER
2 NESTED LOOPS
2 HASH JOIN
2 NESTED LOOPS
2 NESTED LOOPS
2 NESTED LOOPS
330261 REMOTE OF 'TWFLPROCESSINSTANCES' (REMOTE)
[T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "ID","STATUS","STARTDATE"
FROM "DIALOG6"."TWFLPROCESSINSTANCES" "PI" WHERE
"STATUS"<>'A' AND "STATUS"<>'N' AND "STARTDATE">=:1-30
2 REMOTE OF 'TAMCONTRACTEDITEMD' (REMOTE)
[T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "CITEM_ID","ROOTCITEM_ID",
"PRODUCT_ID","CONTRACT_ID" FROM
"DIALOG6"."TAMCONTRACTEDITEMD" "CI" WHERE "PRODUCT_ID"=
934 AND "CONTRACT_ID"=:1
2 REMOTE OF 'TAMPROPVALUES' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "PROPERTY_ID",
"VALUEOBJECT_ID","CONTRACTEDITEM_ID","DTO","ISVALID"
FROM "DIALOG6"."TAMPROPVALUES" "TV" WHERE "DTO" IS NULL
AND "ISVALID"='Y' AND "CONTRACTEDITEM_ID"=:1 AND
"PROPERTY_ID"=930326
2 REMOTE OF 'TREPVALUELISTITEMS' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "ID","NAME" FROM
"DIALOG6"."TREPVALUELISTITEMS" "TVL" WHERE "ID"=:1
24542745 REMOTE OF 'TAMCONTRACTEDITEMD' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "CITEM_ID","CONTRACT_ID" FROM
"DIALOG6"."TAMCONTRACTEDITEMD" "CINAD"
2 REMOTE OF 'TWFLPROCESSINSTANCES' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "ID" FROM
"DIALOG6"."TWFLPROCESSINSTANCES" "SYS_ALIAS_1" WHERE "ID"=
:1
2 INDEX MODE: ANALYZED (RANGE SCAN) OF 'IDX_PROCES_ID'
(INDEX)
********************************************************************************
REMOTE SERVER TKPROF OUTPUT:
call count cpu elapsed disk query current rows
Parse 1 0.15 0.15 0 0 2 0
Execute 1 1210.69 3831.70 0 6 0 0
Fetch 0 0.00 0.00 0 0 0 0
total 2 1210.85 3831.85 0 6 2 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 66 (SPB)
Rows Row Source Operation
0 SORT UNIQUE (cr=6 pr=0 pw=0 time=681448432 us)
0 FILTER (cr=6 pr=0 pw=0 time=681448397 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=681448144 us)
2 HASH JOIN (cr=0 pr=0 pw=0 time=681443808 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=168646003 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=168636029 us)
2 NESTED LOOPS (cr=0 pr=0 pw=0 time=168580989 us)
327667 REMOTE TWFLPROCESSINSTANCES (cr=0 pr=0 pw=0 time=9177863 us)
2 REMOTE TAMCONTRACTEDITEMD (cr=0 pr=0 pw=0 time=158011360 us)
2 REMOTE TAMPROPVALUES (cr=0 pr=0 pw=0 time=55007 us)
2 REMOTE TREPVALUELISTITEMS (cr=0 pr=0 pw=0 time=9947 us)
24542745 REMOTE TAMCONTRACTEDITEMD (cr=0 pr=0 pw=0 time=3509657414 us)
2 REMOTE TWFLPROCESSINSTANCES (cr=0 pr=0 pw=0 time=4309 us)
2 INDEX RANGE SCAN IDX_PROCES_ID (cr=6 pr=0 pw=0 time=160 us)(object id 552075)
Rows Execution Plan
0 INSERT STATEMENT MODE: ALL_ROWS
0 SORT (UNIQUE)
0 FILTER
2 NESTED LOOPS
2 HASH JOIN
2 NESTED LOOPS
2 NESTED LOOPS
2 NESTED LOOPS
327667 REMOTE OF 'TWFLPROCESSINSTANCES' (REMOTE)
[T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "ID","STATUS","STARTDATE"
FROM "DIALOG6"."TWFLPROCESSINSTANCES" "PI" WHERE
"STATUS"<>'A' AND "STATUS"<>'N' AND "STARTDATE">=:1-30
2 REMOTE OF 'TAMCONTRACTEDITEMD' (REMOTE)
[T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "CITEM_ID","ROOTCITEM_ID",
"PRODUCT_ID","CONTRACT_ID" FROM
"DIALOG6"."TAMCONTRACTEDITEMD" "CI" WHERE "PRODUCT_ID"=
934 AND "CONTRACT_ID"=:1
2 REMOTE OF 'TAMPROPVALUES' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "PROPERTY_ID",
"VALUEOBJECT_ID","CONTRACTEDITEM_ID","DTO","ISVALID"
FROM "DIALOG6"."TAMPROPVALUES" "TV" WHERE "DTO" IS NULL
AND "ISVALID"='Y' AND "CONTRACTEDITEM_ID"=:1 AND
"PROPERTY_ID"=930326
2 REMOTE OF 'TREPVALUELISTITEMS' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "ID","NAME" FROM
"DIALOG6"."TREPVALUELISTITEMS" "TVL" WHERE "ID"=:1
24542745 REMOTE OF 'TAMCONTRACTEDITEMD' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "CITEM_ID","CONTRACT_ID" FROM
"DIALOG6"."TAMCONTRACTEDITEMD" "CINAD"
2 REMOTE OF 'TWFLPROCESSINSTANCES' (REMOTE) [T6STDBY.WR]
SELECT /*+ OPAQUE_TRANSFORM */ "ID" FROM
"DIALOG6"."TWFLPROCESSINSTANCES" "SYS_ALIAS_1" WHERE "ID"=
:1
2 INDEX MODE: ANALYZED (RANGE SCAN) OF 'IDX_PROCES_ID'
(INDEX)
Edited by: Przemek P on 2012-01-27 07:40
Edited by: Przemek P on 2012-01-27 07:50