Home » RDBMS Server » Server Utilities » Slow exports using exp command due to open sessions (Oracle 11.1.0.7, SUSE 11 SP1 Linux x86 64bit)
Slow exports using exp command due to open sessions [message #530857] Fri, 11 November 2011 02:51 Go to next message
francl
Messages: 8
Registered: November 2011
Location: Slovenia
Junior Member
I have had the following problem open with Oracle support since March 2011 (8 months), and still no resolution. So I thought I would post here if anyone has any ideas.

When I export all our schema's on Sunday night it takes about 1 hour 50 minutes. When I export the same schema's on any other night it takes 7 hours. The only difference is that on Sunday at 4:00am we drop all connections in the connection pools and reestablish new connections. Then 19hours later on Sunday at 23:00 we perform the exports which only take 2 hours to complete.

I have also tried recreating the connections in the connection pools during the week, and the exports have then only taken 2 hours to complete. But the following night after the connections have been used during the day, the exports again take 7 hours. So it appears the export speed gets significantly slower when there are many open connections that have been used and not closed.

From the stats pack report I found 2 SQL statements internal to the export command, that had an order of magnitude in difference when looking at the elapsed execution time between the fast export, and the slow export (see below).

If anyone has similar problems or has any ideas on how to speed up the exports without having to drop and recreate the database connections in the connection pools each night please let me know.

FAST:
elapsed_time: 430.90
executions: 161,388
Module: exp@Oracle1 (TNS V1-V3)
SELECT COLNAME, COLNO, PROPERTY, NOLOG FROM SYS.EXU10CCL
WHERE CNO = :1 ORDER BY COLNO

elapsed_time: 264.29
executions: 50,349
Module: exp@Oracle1 (TNS V1-V3)
SELECT TOWNER, TNAME, NAME, LENGTH, PRECISION, SCALE, TYPE, ISNULL, CONNAME, COLID, INTCOLID, SEGCOLID, COMMENT$, DEFAULT$, DFLTLEN, ENABLED, DEFER, FLAGS, COLPROP, ADTNAME, ADTOWNER, CHARSETID, CHARSETFORM, FSPRECISION, LFPRECISION, CHARLEN, TFLAGS, 100 FROM SYS.EXU8COL
WHERE TOBJID = :1 ORDER BY INTCOLID


SLOW:
elapse_time: 8264.16
executions: 124,662
Module: exp@Oracle1 (TNS V1-V3)
SELECT COLNAME, COLNO, PROPERTY, NOLOG FROM SYS.EXU10CCL
WHERE CNO = :1 ORDER BY COLNO

elapsed_time: 3877.78
executions: 38,813
Module: exp@Oracle1 (TNS V1-V3)
SELECT TOWNER, TNAME, NAME, LENGTH, PRECISION, SCALE, TYPE, ISNULL, CONNAME, COLID, INTCOLID, SEGCOLID, COMMENT$, DEFAULT$, DFLTLEN, ENABLED, DEFER, FLAGS, COLPROP, ADTNAME, ADTOWNER, CHARSETID, CHARSETFORM, FSPRECISION, LFPRECISION, CHARLEN, TFLAGS, 100 FROM SYS.EXU8COL
WHERE TOBJID = :1 ORDER BY INTCOLID

I use the following export command for each schema:
$ORACLE_HOME/bin/exp user/pass file=somefile.dmp owner=$SCHEMA log=somelog.log buffer=9000000

I have an Oracle Standard edition 11.1.0.7 database on 64bit Linux with a 7GB SGA. I currently export (I use exp not datapump because datapump is a lot slower and we can't use parallel processing features of datapump on a standard edition database) approx 200 schema's each night. The export normally takes 1 hour 50 minutes which is approximately 2 schema's exported every minute. When the exports run slowly each export takes almost 2 minutes to complete.
The database has about 20 GB data and 50 GB indexes. The database has also approx 500 connections via toplink connection pools from 8 application servers.
Re: Slow exports using exp command due to open sessions [message #530953 is a reply to message #530857] Fri, 11 November 2011 08:09 Go to previous messageGo to next message
BlackSwan
Messages: 26656
Registered: January 2009
Location: SoCal
Senior Member
consider SQL_TRACE=TRUE for both cases & compare where time is actually being spent
by detailed inspection of actual traces files.
Re: Slow exports using exp command due to open sessions [message #531167 is a reply to message #530953] Mon, 14 November 2011 04:20 Go to previous message
francl
Messages: 8
Registered: November 2011
Location: Slovenia
Junior Member
Here is I believe the important section of my SQL TRACE output for the slow and fast export scenarios. The biggest differences can be seen at lines 2 and 3 in my summary and 3 and 4. Also the timestamp on the FETCH output for the fast case appears strange. It appears that SQL TRACE did not update the time stamp even though it did for the WAIT statements.

I can see that there is a discrepancy in the times but I still don't know how to find out what is causing the discrepancy? Can anyone suggest where to go from here ?
Can anyone explain the SQL TRACE output and what it means, I am not sure I have interpreted it correctly.

SUMMARY: See below for SQL TRACE output
		TIME STAMP SLOW CASE	diff		TIME STAMP FAST CASE	diff

1 PARSE		tim=1321259092073989			tim=1321258936566653
2 EXEC		tim=1321259092073989	0		tim=1321258936566653	0
3 WAIT		tim=1321259092082601	8612	        tim=1321258936571117	4464
4 FETCH		tim=1321259092134018	51417	        tim=1321258936566653	-4464 ????
5 WAIT		tim=1321259092139384	5366	        tim=1321258936575019	3902
...
6 WAIT		tim=1321259092140374	990		tim=1321258936576304	1285
7 WAIT		tim=1321259092140766	392		tim=1321258936576720	416


SLOW CASE:

PARSING IN CURSOR #2 len=87 dep=0 uid=0 oct=3 lid=0 tim=1321259092073989 hv=2746115949 ad='1ec921d30' sqlid='5t956r6juwtvd'
SELECT COLNAME, COLNO, PROPERTY, NOLOG FROM SYS.EXU10CCL WHERE CNO = 302 ORDER BY COLNO
END OF STMT
PARSE #2:c=48003,e=60037,p=2,cr=64,cu=0,mis=1,r=0,dep=0,og=1,plh=2201906051,tim=1321259092073989
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2201906051,tim=1321259092073989
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321259092082601
FETCH #2:c=8000,e=60029,p=0,cr=41,cu=0,mis=0,r=1,dep=0,og=1,plh=2201906051,tim=1321259092134018
WAIT #2: nam='SQL*Net message from client' ela= 467 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321259092139384
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2201906051,tim=1321259092134018
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=41 pr=0 pw=0 time=0 us cost=43 size=6093 card=3)'
...
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321259092140374
WAIT #2: nam='SQL*Net message from client' ela= 375 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321259092140766



FAST CASE:

PARSING IN CURSOR #2 len=87 dep=0 uid=0 oct=3 lid=0 tim=1321258936566653 hv=2746115949 ad='8abcdb80' sqlid='5t956r6juwtvd'
SELECT COLNAME, COLNO, PROPERTY, NOLOG FROM SYS.EXU10CCL WHERE CNO = 302 ORDER BY COLNO
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2201906051,tim=1321258936566653
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2201906051,tim=1321258936566653
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321258936571117
FETCH #2:c=0,e=0,p=0,cr=41,cu=0,mis=0,r=1,dep=0,og=1,plh=2201906051,tim=1321258936566653
WAIT #2: nam='SQL*Net message from client' ela= 668 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321258936575019
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2201906051,tim=1321258936566653
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=41 pr=0 pw=0 time=0 us cost=43
...
WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321258936576304
WAIT #2: nam='SQL*Net message from client' ela= 397 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1321258936576720

[Updated on: Mon, 14 November 2011 04:24]

Report message to a moderator

Previous Topic: SQL loader
Next Topic: Transportable tablespace.
Goto Forum:
  


Current Time: Wed Feb 19 14:33:37 CST 2020