NDMP backup log shows out of order written data numbers

aborzenkov · ‎2008-10-05

I am looking at possible bottlenecks in NDMP backup from FAS3050 and tripped over something strange. The system is using DOT 7.2.4P6 and NetWorker 7.3 on Linux 64 bit; NDMP is done over the network using NetWorker as DSA (no direct tape connection to NetApp).

While looking at NDMP throughput I found that amount od written data is not increased consistently. Now I am not sure whether this is NetApp bug, NetWorker bug or real problems that cause NDMP to restart from some earlier point. Here is example of output:

20081001-030340 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: dumping (Pass IV) NDMP backup log shows out of order written data numbers

20081001-030755 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:07:55 2008 : We have written 10177538 KB.

20081001-031413 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:14:13 2008 : We have written 17597169 KB.

20081001-031924 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:19:23 2008 : We have written 26366372 KB.

20081001-032423 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:24:23 2008 : We have written 33856530 KB.

20081001-032923 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:29:23 2008 : We have written 46497152 KB.

20081001-033423 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:34:23 2008 : We have written 59053749 KB.

20081001-033923 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:39:23 2008 : We have written 71711304 KB.

20081001-034423 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:44:23 2008 : We have written 283034449 KB.

20081001-034923 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:49:23 2008 : We have written 97020679 KB.

20081001-035423 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:54:23 2008 : We have written 109380798 KB.

20081001-035923 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 03:59:23 2008 : We have written 120547466 KB.

20081001-040423 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 04:04:23 2008 : We have written 331647331 KB.

20081001-040923 ndmp_wait_for_saves: nsrndmp_save: NDMP Service Log: DUMP: Wed Oct 1 04:09:23 2008 : We have written 136112506 KB.

I also tested plain dump to nul and did not get this which makes me suspect NetWorker side.

Anyone has seen this before?

BrendonHiggins · ‎2008-10-08

We get the same when using the NetApp dump command

DUMP: Wed Oct 8 09:36:03 2008 : We have written 12171357 KB.
DUMP: Wed Oct 8 09:41:03 2008 : We have written 20544282 KB.
DUMP: Wed Oct 8 09:46:03 2008 : We have written 29993675 KB.
DUMP: Wed Oct 8 09:51:03 2008 : We have written 41954547 KB.
DUMP: Wed Oct 8 09:56:03 2008 : We have written 49832517 KB.
DUMP: Wed Oct 8 10:01:03 2008 : We have written 62894254 KB.
DUMP: Wed Oct 8 10:06:03 2008 : We have written 74287127 KB.
DUMP: Wed Oct 8 10:11:03 2008 : We have written 81476987 KB.
DUMP: Wed Oct 8 10:16:03 2008 : We have written 92293302 KB.
DUMP: Wed Oct 8 10:21:03 2008 : We have written 102043188 KB.
DUMP: Wed Oct 8 10:26:03 2008 : We have written 109377100 KB.
DUMP: Wed Oct 8 10:31:03 2008 : We have written 118608865 KB.
DUMP: Wed Oct 8 10:36:03 2008 : We have written 128666822 KB.
DUMP: Wed Oct 8 10:41:03 2008 : We have written 136145413 KB.
DUMP: Wed Oct 8 10:46:03 2008 : We have written 147173255 KB.
DUMP: Wed Oct 8 10:51:03 2008 : We have written 157383268 KB.

And when we use NDMP via HP data protector.

The thoughput drops when the filer is busy, snapmirrors etc.

aborzenkov · ‎2008-10-08

But your numbers are perfectly increasing and my jumping forward and backward. Look:

2008 : We have written 71711304 KB.

DUMP: Wed Oct 1 03:44:23 2008 : We have written 283034449 KB.

DUMP: Wed Oct 1 03:49:23 2008 : We have written 97020679 KB.

DUMP: Wed Oct 1 03:54:23 2008 : We have written 109380798 KB

I possibly was not clear enough - these numbers are expected to be total amount since beginning of NDMP session. It is rather hard to believe that after dumping total of 283034449 KB it suddenly jumps back and dumps 97020679 KB. But it makes analysis of real progress rather impossible - I have no idea which of both numbers is correct.

BrendonHiggins · ‎2008-10-08

Phase IV is the writing of data so it could be the screen is showing estimated size and the then finding out the 'real' size once it has written the data to media.

You can turn on ndmp debug on the filer but it does send out a great deal of data.

ndmpd debug 70

turn on

ndmpd debug 0

turn off