Data Pump’s amazingly useful METRICS=Y and LOGTIME=ALL parameters

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!