This was first published on https://blog.dbi-services.com/datapump-processing-object-type-misleading-messages (2016-01-18)
Republishing here for new followers. The content is related to the the versions available at the publication date
You’ve started a long DataPump and see it stuck on TABLE/STATISTICS/TABLE_STATISTICS, but you don’t expect that step to take a long time. Let’s see if we can rely on that message. I’ve a 500MB table and export it. I’ll use the 12c LOGTIME option to print a timestamp in front of each output line:
18-JAN-16 21:35:44.038: Starting "SOE"."SYS_EXPORT_TABLE_01": soe/********@//localhost/SWINGBENCH tables=soe.DEMO directory=tmp status=1 logtime=all reuse_dumpfiles=y 18-JAN-16 21:35:48.294: Processing object type TABLE_EXPORT/TABLE/TABLE 18-JAN-16 21:35:48.687: Processing object type TABLE_EXPORT/TABLE/TABLE_DATA 18-JAN-16 21:35:49.532: Processing object type TABLE_EXPORT/TABLE/INDEX/INDEX 18-JAN-16 21:35:49.849: Processing object type TABLE_EXPORT/TABLE/INDEX/STATISTICS/INDEX_STATISTICS 18-JAN-16 21:35:50.242: Processing object type TABLE_EXPORT/TABLE/STATISTICS/TABLE_STATISTICS 18-JAN-16 21:35:54.779: . . exported "SOE"."DEMO" 542.6 MB 5051504 rows 18-JAN-16 21:35:55.257: Processing object type TABLE_EXPORT/TABLE/STATISTICS/MARKER 18-JAN-16 21:35:55.644: Master table "SOE"."SYS_EXPORT_TABLE_01" successfully loaded/unloaded 18-JAN-16 21:35:55.693: ****************************************************************************** 18-JAN-16 21:35:55.694: Dump file set for SOE.SYS_EXPORT_TABLE_01 is: 18-JAN-16 21:35:55.697: /tmp/expdat.dmp 18-JAN-16 21:35:55.738: Job "SOE"."SYS_EXPORT_TABLE_01" successfully completed at Mon Jan 18 21:35:55 2016 elapsed 0 00:00:13If you rely on the ‘Processing’ messages, the export of table data takes 49.532 – 48.687 = 0.845 seconds. And exporting table statistics takes 55.257 – 50.242 = 5 seconds. Obviously, this is wrong.
When you look at the ‘exported … rows’ it seems that the export of table data was still running at that time.
As you can see above, I’ve run the expdp with the STATUS=1 in order to display job status every 1 second.
After the TABLE_EXPORT/TABLE/TABLE_DATA the worker was not executing:
Worker 1 Status: Instance ID: 1 Instance name: CDB Host name: VM117 Object start time: Monday, 18 January, 2016 21:35:48 Object status at: Monday, 18 January, 2016 21:35:48 Process Name: DW00 State: WORK WAITINGThen it changed to the state of EXECUTING for several seconds.
Only at 21:35:51 we can see a status showing that it’s working on the table export, which is more than 1 second after the related ‘Processing’ message:
Worker 1 Status: Instance ID: 1 Instance name: CDB Host name: VM117 Object start time: Monday, 18 January, 2016 21:35:51 Object status at: Monday, 18 January, 2016 21:35:51 Process Name: DW00 State: EXECUTING Object Schema: SOE Object Name: DEMO Object Type: TABLE_EXPORT/TABLE/TABLE_DATA Completed Objects: 1 Total Objects: 1 Completed Rows: 1,398,529 Worker Parallelism: 1
Then, the status displayed every seconds shows the same with an increasing number of rows until 21:35:54:
Worker 1 Status: Instance ID: 1 Instance name: CDB Host name: VM117 Access method: direct_path Object start time: Monday, 18 January, 2016 21:35:51 Object status at: Monday, 18 January, 2016 21:35:54 Process Name: DW00 State: EXECUTING Object Schema: SOE Object Name: DEMO Object Type: TABLE_EXPORT/TABLE/TABLE_DATA Completed Objects: 1 Total Objects: 1 Completed Rows: 5,051,504 Completed Bytes: 569,032,224 Percent Done: 100 Worker Parallelism: 1and this is where we get the message:
18-JAN-16 21:35:54.779: . . exported "SOE"."DEMO" 542.6 MB 5051504 rows
Then we can see the following status which suggests that TABLE_EXPORT/TABLE/STATISTICS/MARKER has started:
Worker 1 Status: Instance ID: 1 Instance name: CDB Host name: VM117 Object start time: Monday, 18 January, 2016 21:35:51 Object status at: Monday, 18 January, 2016 21:35:55 Process Name: DW00 State: EXECUTING Object Schema: SYS Object Type: TABLE_EXPORT/TABLE/STATISTICS/MARKER Worker Parallelism: 1but we see the related ‘Processing’ message only after it:
18-JAN-16 21:35:55.257: Processing object type TABLE_EXPORT/TABLE/STATISTICS/MARKERStrange to take 4 seconds on that step, and anyway the ‘Processing…’ message comes at the end here.
My first conclusion here is that you should not rely on the ‘Processing…’ messages to know what is currently running. If you’ve run expdp from your terminal, you can interrupt it with control-C and you have a CLI to control the worker processes. They are still running and you can see the status with STATUS and then continue to the previous mode with CONTINUE_CLIENT. If expdp is running in background, you can attach to the job and do the same. Remember that DataPump is running through background jobs, which explains that the ‘Processing’ message may not be in sync with what is currently processed.
So, the ‘LOGTIME’ option a bit useless when it puts the timestamp in front the ‘Processing’ messages. However, it’s useful for the ‘exported’ message as it is the end of the table export.