By Franck Pachot

.
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:13

If 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 WAITING

Then 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: 1

and 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: 1

but we see the related ‘Processing’ message only after it:


18-JAN-16 21:35:55.257: Processing object type TABLE_EXPORT/TABLE/STATISTICS/MARKER

Strange to take 4 seconds on that step, and anyway the ‘Processing…’ message comes at the end here. Actually, this step is waiting for the previous one to finish.

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.

Post Views: 758
Thumbnail [60x60]
by
Oracle Team