Home » RDBMS Server » Server Utilities » expdp slow, delays in QUEUE_INT.SEND (Oracle 11.2.0.4, Windows Server 2012 R2)
expdp slow, delays in QUEUE_INT.SEND [message #665348] Thu, 31 August 2017 14:25 Go to next message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
I have three 11.2.0.4 Oracle instances on a Windows 2012 R2 server. One instance is fine and does not exhibit the behavior described below.

For the other two, expdp is painfully slow. With METRICS=Y, the output shows the startup phase taking anywhere from 60 to 120 seconds. Once the actual data export gets underway, every table takes a minimum of 2-3 seconds, including empty tables. With TRACE set to 0690300 (typical 0480300, plus 0010000 for expdp/impdp details, plus 0200000 for queue services details), the trace log shows a delay of 2-3 seconds on every "KUPC$QUEUE_INT.SEND".

Here, note the delay of 2.709 seconds between "...SEND called" and "...SEND returned". Also note MYSCHEMA.MYTABLE is empty.

KUPW:11:47:27.095: 2: In procedure BUILD_OBJECT_STRINGS
KUPW:11:47:27.095: 2: In procedure MOVE_DATA UNLOADing process_order 2 TABLE_DATA:"MYSCHEMA"."MYTABLE"
KUPW:11:47:27.095: 2: In procedure FORMAT_TABLE_DATA_MSG
KUPW:11:47:27.095: 2: In procedure CREATE_MSG
KUPW:11:47:27.095: 2: KUPV$FT.MESSAGE_TEXT called. 
KUPW:11:47:27.095: 2: KUPV$FT.MESSAGE_TEXT returned. 
KUPW:11:47:27.095: 2: In procedure SEND_MSG. Fatal=0
KUPW:11:47:27.095: 2: KUPC$QUEUE_INT.SEND called. 

*** 2017-08-31 11:47:29.804
KUPW:11:47:29.804: 2: KUPC$QUEUE_INT.SEND returned. 
KUPW:11:47:29.804: 2: . . exported "MYSCHEMA"."MYTABLE"                 0 KB       0 rows

Following advice on the internet, in the two slow instances, I rebuilt all indexes and analyzed all tables in MYSCHEMA; gathered dictionary stats, system stats, and fixed object stats; confirmed (to the best of my ability) that things like memory_target, memory_max_target, and streams_pool_size are all set appropriately. I also confirmed there are no invalid objects in SYS or SYSTEM (or in fact anywhere in any instance). The queue tables in all three schemas are defined identically.

In one of the slow instances, gathering dictionary/system/fixed-object stats was the key to the kingdom. Once I did that, expdp startup in that instance became nearly instantaneous, exporting an empty table is nearly instantaneous, the delays on QUEUE_INT.SEND in the trace log are gone, and a schema backup that ran nearly two hours the night before completed in under three minutes. This is the kind of performance I am expecting. In the other slow schema, despite taking all the same steps, expdp performance remains exactly the same, as shown in the trace log entry above.

A colleague suggested bumping AQ_TM_PROCESSES from 1 to 2. The internet is clear that I shouldn't need to fool with that parameter in 11g at all, and equally clear that it should never be set to zero (it wasn't), but somewhat less clear on what effect (if any) that parameter still has in 11g. At any rate, I tried bumping it from 1 to 2, and this had no effect either

What am I missing?

Re: expdp slow, delays in QUEUE_INT.SEND [message #665350 is a reply to message #665348] Thu, 31 August 2017 21:47 Go to previous messageGo to next message
BlackSwan
Messages: 25639
Registered: January 2009
Location: SoCal
Senior Member
When you see a difference in performance, you can be 100% assured that something is in fact different.
Since we can not compare & contrast the slow database against the two normal database, it is up to you to locate where the difference actually exists.
Re: expdp slow, delays in QUEUE_INT.SEND [message #665351 is a reply to message #665350] Thu, 31 August 2017 22:59 Go to previous messageGo to next message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
Understood and agreed. I need to narrow it down, though. The three instances are not identical - a small one supports product A, a small-to-medium supports final ready-for-production testing of product B, and a larger one supports development & testing of that same product B but with more full and partial schemas. There are differences between them that surely don't matter... and I agree completely, there is obviously at least one critical difference, something that would explain why I had no problem in the first, and the problem went away in the second, and the problem remains in the third. I believe the two instances that are now working properly rule out a hardware problem, and they largely rule out a software problem as well (i.e. Oracle bug/patch, although not entirely ruled out).

Suppose I had an Oracle 11.2.0.4 instance with expdp symptoms as described, slow startup, 2-3 second delays between tables regardless of size, trace logs showing that delay is between "QUEUE_INT.SEND called" and "QUEUE_INT.SEND return"... all as described above... but suppose I hadn't mentioned the other two instances at all. I would greatly appreciate any suggestions or advice for anything I might check, tests I could run, trace options I could turn on, log messages to look for, anything at all that could lead to an explanation for why this instance is displaying these symptoms, without regard to any other instances that are not.
Re: expdp slow, delays in QUEUE_INT.SEND [message #665352 is a reply to message #665351] Fri, 01 September 2017 00:51 Go to previous messageGo to next message
John Watson
Messages: 7065
Registered: January 2010
Location: Global Village
Senior Member
How did you analyze your data dictionary? To be sure of adequate statistics, I would do it like this:
exec dbms_Stats.gather_dictionary_Stats(estimate_percent=>100,method_opt=>'for all columns size skewonly',granularity=>'all',options=>'gather')
Re: expdp slow, delays in QUEUE_INT.SEND [message #665365 is a reply to message #665352] Fri, 01 September 2017 08:20 Go to previous messageGo to next message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
I'm having connectivity issues this morning so can't get in to double-check, but I think I did this:
dbms_stats.gather_dictionary_stats
dbms_stats.gather_database_stats(gather_sys=>TRUE)
dbms_stats.gather_schema_stats('SYS')

I'll check on what I did and try your suggestion as soon as I can get in there to see. Thanks!
Re: expdp slow, delays in QUEUE_INT.SEND [message #665431 is a reply to message #665365] Tue, 05 September 2017 08:45 Go to previous messageGo to next message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
Sorry for the delay, long holiday weekend.

Upon further review what I did before was:
EXEC DBMS_STATS.GATHER_DICTIONARY_STATS;
EXEC DBMS_STATS.GATHER_SYSTEM_STATS;
EXEC DBMS_STATS.GATHER_FIXED_OBJECTS_STATS (null);

This morning, I confirmed the problem hadn't magically disappeared, then did this as suggested:
exec dbms_Stats.gather_dictionary_Stats(estimate_percent=>100,method_opt=>'for all columns size skewonly',granularity=>'all',options=>'gather')

...and the problem remains, with the "startup" phase reporting 45-120 seconds and then each table having a 2-3 second delay in KUPC$QUEUE_INT.SEND. With TRACE set to 0690300 (typical 0480300, plus 0010000 for impdp/expdp trace, plus 0200000 for queue service trace):
KUPW:09:39:25.139: 2: In procedure SEND_MSG. Fatal=0
KUPW:09:39:25.139: 2: KUPC$QUEUE_INT.SEND called. 
KUPC:09:39:25.139: Before ENQ: Sending Type: 3031 ID:
KUPC:09:39:25.139:  DG,KUPC$C_1_20170905093341,KUPC$A_1_093553732000000,MCP,31,Y

*** 2017-09-05 09:39:27.373
KUPW:09:39:27.373: 2: KUPC$QUEUE_INT.SEND returned. 
KUPW:09:39:27.373: 2: . . exported "SCHEMANAME"."TABLENAME"          0 KB  
Re: expdp slow, delays in QUEUE_INT.SEND [message #665468 is a reply to message #665431] Wed, 06 September 2017 11:31 Go to previous messageGo to next message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
SOLVED.

Yesterday, I had gathered dictionary statistics using the syntax suggested by John Watson above, at around 9:25am. Then I ran my test expdp to export 30 empty tables; that test (around 9:39am as shown in the trace log above) still took four minutes, same as before. I ran that same test expdp today, and it completed in ten seconds.

It appears something changed at 9:54 am yesterday. Looking at other logs, my overnight expdp's on various similarly-sized schemas were averaging 13 minutes each until 9:54am yesterday, and then about one minute each after 9:55am. I don't know if it just took a while for gather_dictionary_stats to really "take", or if something else changed (no idea what), but any way you slice it, my expdp problem appears to be solved.

Thanks, everyone, and especially John Watson!


(Edit: added time of yesterday's test vs time of gather_dictionary_stats vs time performance suddenly returned to normal.)

[Updated on: Wed, 06 September 2017 11:52]

Report message to a moderator

Re: expdp slow, delays in QUEUE_INT.SEND [message #665509 is a reply to message #665468] Thu, 07 September 2017 21:24 Go to previous messageGo to next message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
A note for the future forum-searcher (and there's a nonzero chance that person will be me). (Hello future me!)

The first instance that was slow but got fast again after gathering stats mysteriously went slow again, taking 6 minutes to export 30 empty tables, with delays in startup and in the trace file as described above. Gathering dictionary stats with John Watson's suggested syntax had no immediate effect, nor any apparent effect a couple of hours later. Then bumping streams_pool_size from default 0 to 300mb had immediate effect, bringing that instance's expdp back to full speed, exporting those same 30 tables in 9 seconds start to finish.

[Updated on: Thu, 07 September 2017 21:25]

Report message to a moderator

Re: expdp slow, delays in QUEUE_INT.SEND [message #665639 is a reply to message #665509] Wed, 13 September 2017 10:18 Go to previous messageGo to next message
Flyby
Messages: 179
Registered: March 2011
Location: Belgium
Senior Member
Thanks for the update
stream_pool_size triggers a memory
Re: expdp slow, delays in QUEUE_INT.SEND [message #665835 is a reply to message #665348] Mon, 25 September 2017 08:18 Go to previous message
ctvarner
Messages: 8
Registered: August 2017
Junior Member
.....aaaaaaaaand then they slowed down again, with no changes applied to the DB.

Blog post import-data-pump-performance-problem describes my situation well, and it identifies Bug 21286665 as the culprit.

The fix for that bug was included in the April 2017 bundle, and the April bundle was installed on the affected server in early August (before this problem became apparent). For lack of anything else to try, we installed the August 2017 bundle - which is all-inclusive, including all patches from April - and lo & behold, that seems to have resolved the problem. It's been several days and the expdp's are screaming fast. My only theory is that the April patch bundle was not installed correctly.

To put the before/after in perspective, a big set of expdp's ran 13.5 hours before we killed it to install the patch bundle. Afterward the patch, we restarted that set of expdp's from the top, and it got back to the same point where we had killed it ... in ten minutes.

(EDIT: I just realized Flyby's link above points to the same blog post. Sweet!)

[Updated on: Mon, 25 September 2017 09:03]

Report message to a moderator

Previous Topic: IMP-00017: following statement failed with ORACLE error 922
Goto Forum:
  


Current Time: Mon Sep 25 21:08:33 CDT 2017

Total time taken to generate the page: 0.01520 seconds