Now that I am back from OpenWorld, I will hijack the Upgrade blog while Mike is traveling. 🙂
Thank you to everybody who came to our presentations or stopped at the demo booth to chat last week. We had a great many conversations, and we always learn from talking to customers! One of the common questions about Data Pump came in the form, “I have a data pump job that used to run in X minutes, but now takes <multiple of X> minutes. Can you tell me what might be happening?“
Of course with that much information we can do very little. This is true even if we know that you moved from one version to another, or from one operating system to another. What we really need is some data to start with. That is where the METRICS and LOGTIME parameters are very useful.
Let’s start by looking at a fragment of a logfile. This is from a metadata-only export of an E-Business Suite database on our small test system. If I told you that this particular export took 2h 20m to complete, how would you know which parts took a long time and which completed faster? Here is part of the default logfile:
Processing object type DATABASE_EXPORT/EARLY_POST_INSTANCE_IMPCALLOUT/MARKER Processing object type DATABASE_EXPORT/SCHEMA/XMLSCHEMA/XMLSCHEMA Processing object type DATABASE_EXPORT/NORMAL_OPTIONS/TABLE Processing object type DATABASE_EXPORT/NORMAL_OPTIONS/VIEWS_AS_TABLES/TABLE Processing object type DATABASE_EXPORT/NORMAL_POST_INSTANCE_IMPCALLOU/MARKER Processing object type DATABASE_EXPORT/SCHEMA/TABLE/PROCACT_INSTANCE Processing object type DATABASE_EXPORT/SCHEMA/TABLE/TABLE Processing object type DATABASE_EXPORT/SCHEMA/TABLE/GRANT/OWNER_GRANT/OBJECT_GRANT Processing object type DATABASE_EXPORT/SCHEMA/TABLE/GRANT/WITH_GRANT_OPTION/OBJECT_GRANT
The default logfile gives you an accounting of what was done in which order, but precious little in the way of performance data. Now let’s see what happens when we specify METRICS=Y for that same export. The METRICS parameter has been around for a long time, and has been documented since Oracle Database 11g Release 2 (11.2). It has the very useful effect of adding information to the logfile that tells you (and us) how long it took to export a particular type of database object. :
Processing object type DATABASE_EXPORT/EARLY_POST_INSTANCE_IMPCALLOUT/MARKER Completed 1 MARKER objects in 88 seconds Processing object type DATABASE_EXPORT/SCHEMA/XMLSCHEMA/XMLSCHEMA Completed 3 XMLSCHEMA objects in 1 seconds Processing object type DATABASE_EXPORT/NORMAL_OPTIONS/TABLE Completed 64 TABLE objects in 98 seconds Processing object type DATABASE_EXPORT/NORMAL_OPTIONS/VIEWS_AS_TABLES/TABLE Completed 10 TABLE objects in 121 seconds Processing object type DATABASE_EXPORT/NORMAL_POST_INSTANCE_IMPCALLOU/MARKER Completed 1 MARKER objects in 20 seconds Processing object type DATABASE_EXPORT/SCHEMA/TABLE/PROCACT_INSTANCE Completed 48 PROCACT_INSTANCE objects in 2 seconds Processing object type DATABASE_EXPORT/SCHEMA/TABLE/TABLE Completed 33263 TABLE objects in 343 seconds Processing object type DATABASE_EXPORT/SCHEMA/TABLE/GRANT/OWNER_GRANT/OBJECT_GRANT Completed 358621 OBJECT_GRANT objects in 614 seconds Processing object type DATABASE_EXPORT/SCHEMA/TABLE/GRANT/WITH_GRANT_OPTION/OBJECT_GRANT Completed 102 OBJECT_GRANT objects in 7 seconds
Here we get a sense of what took time or not in the processing. But, there are cases where the rounding error of reporting in full seconds is too large — particularly when you have a job containing thousands of small tables. Let’s get more granular measurements by specifying the LOGTIME parameter, which was introduced in Oracle Database 12c. Here is the logfile for that same job, but this time specifying LOGTIME=ALL in addition to METRICS=Y:
18-SEP-16 11:05:43.156: Processing object type DATABASE_EXPORT/EARLY_POST_INSTANCE_IMPCALLOUT/MARKER 18-SEP-16 11:05:44.815: Completed 1 MARKER objects in 88 seconds 18-SEP-16 11:05:44.818: Processing object type DATABASE_EXPORT/SCHEMA/XMLSCHEMA/XMLSCHEMA 18-SEP-16 11:05:46.755: Completed 3 XMLSCHEMA objects in 1 seconds 18-SEP-16 11:05:46.768: Processing object type DATABASE_EXPORT/NORMAL_OPTIONS/TABLE 18-SEP-16 11:07:44.876: Completed 64 TABLE objects in 98 seconds 18-SEP-16 11:07:44.879: Processing object type DATABASE_EXPORT/NORMAL_OPTIONS/VIEWS_AS_TABLES/TABLE 18-SEP-16 11:09:43.716: Completed 10 TABLE objects in 121 seconds 18-SEP-16 11:09:43.717: Processing object type DATABASE_EXPORT/NORMAL_POST_INSTANCE_IMPCALLOU/MARKER 18-SEP-16 11:09:45.477: Completed 1 MARKER objects in 20 seconds 18-SEP-16 11:09:45.478: Processing object type DATABASE_EXPORT/SCHEMA/TABLE/PROCACT_INSTANCE 18-SEP-16 11:09:49.218: Completed 48 PROCACT_INSTANCE objects in 2 seconds 18-SEP-16 11:09:49.219: Processing object type DATABASE_EXPORT/SCHEMA/TABLE/TABLE 18-SEP-16 11:15:35.060: Completed 33263 TABLE objects in 343 seconds 18-SEP-16 11:15:35.061: Processing object type DATABASE_EXPORT/SCHEMA/TABLE/GRANT/OWNER_GRANT/OBJECT_GRANT 18-SEP-16 11:25:48.739: Completed 358621 OBJECT_GRANT objects in 614 seconds 18-SEP-16 11:25:48.741: Processing object type DATABASE_EXPORT/SCHEMA/TABLE/GRANT/WITH_GRANT_OPTION/OBJECT_GRANT 18-SEP-16 11:25:50.554: Completed 102 OBJECT_GRANT objects in 7 seconds
As you can see, the LOGTIME parameter adds a timestamp down to the millisecond for every line in your logfile. This can be helpful in diagnosing issues with I/O, where the difference between a table taking 0.123 seconds and 0.059 seconds to export might seem small…unless you have 50,000 or so tables in your database.
So, next time you open an SR or talk to us about data pump performance, we will give you a big (virtual) hug if you specify METRICS=Y and LOGTIME=ALL for your data pump jobs. Even if we eventually need to ask for tracing, these parameters will help us identify the exact tracing needed and speed up analysis immensely!