Re: ndmp backup stopping

william · ‎2015-11-19

I'm having an issue backing up with NDMP using bareos.

I backed up several small volumes (about 13G worth) with no problem.

However when I went to backup a larger volume around 300G, everything seems to be moving a long fine and then I start getting these "buffer full for ndmp_io_process" messages repeated over and over again.

Can anyone tell me what might be happening ?

I'm going to try enabling debugging on the netapp and in bareos and see if I can find out anymore information.

0000000f.001a1ff3 17f3ece7 Thu Nov 19 2015 12:22:06 -08:00 [kern_ndmpd:info:1705] [50720] INFO: DATA&colon; start backup request: VFS='/vol/na3_2_ftp' LEVEL=0 UPDATE HISTORY
0000000f.001a1ff6 17f3ece7 Thu Nov 19 2015 12:22:06 -08:00 [kern_ndmpd:info:1705] [50720] INFO: DATA notification state 1 (SESS_STATE: LISTENING) event 10 (EVENT: STATE CHANGE)
0000000f.001a1ff7 17f3ece7 Thu Nov 19 2015 12:22:06 -08:00 [kern_ndmpd:info:1705] [50720] INFO: DATA&colon; query 0 bytes in DATA_OP_BACKUP (0)
0000000f.001a1ff8 17f3ece7 Thu Nov 19 2015 12:22:06 -08:00 [kern_ndmpd:info:1705] [50720] INFO: DATA notification state 4 (SESS_STATE: ACTIVE) event 10 (EVENT: STATE CHANGE)
0000000f.001a1ff9 17f3eee9 Thu Nov 19 2015 12:22:58 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer full for ndmp_io_process (fd=9) count total 27758284 (5)
0000000f.001a1ffa 17f3ef80 Thu Nov 19 2015 12:23:13 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer full for ndmp_io_process (fd=9) count total 30458444 (20)
0000000f.001a1ffb 17f3f015 Thu Nov 19 2015 12:23:28 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer full for ndmp_io_process (fd=9) count total 34126228 (35)
0000000f.001a1ffc 17f3f0ab Thu Nov 19 2015 12:23:43 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer full for ndmp_io_process (fd=9) count total 38012660 (50)
0000000f.001a1ffd 17f3f141 Thu Nov 19 2015 12:23:58 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer blocked for ndmp_io_process (fd=9) count total 40286020 (40187610)
0000000f.001a2000 17f3f449 Thu Nov 19 2015 12:25:15 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer full for ndmp_io_process (fd=9) count total 40567108 (14) (-0:00:57)
0000000f.001a2001 17f3f4ef Thu Nov 19 2015 12:25:32 -08:00 [kern_ndmpd:info:1705] [50720] INFO: buffer full for ndmp_io_process (fd=9) count total 40567108 (31) (-0:00:57)

Thanks,

William

hariprak · ‎2015-11-27

Hi

Can you provide us NDMP debug log on the storage system.

Thanks

If this post resolved your issue, help others by selecting ACCEPT AS SOLUTION or adding a KUDO.

bastian_dittchrist · ‎2016-01-22

which ontap version are you using?

I have a customer with exact the same problem. with ontap 8.2.3P3 7mode

stevenro72 · ‎2016-09-23

Hi we are seeing exactly the same issue where I work:

Sat Sep 17 2016 20:02:50 +01:00 [kern_ndmpd:info:4503] [ 4503]   INFO: Starting ndmp for client [10.54.48.51].61726
0000001c.0002a6b5 050f8ad1 Sat Sep 17 2016 20:24:54 +01:00 [kern_ndmpd:info:4503] [ 4503]   INFO: Starting ndmp for client [10.54.48.51].63553
0000001c.0002a6b6 050f8ad1 Sat Sep 17 2016 20:24:54 +01:00 [kern_ndmpd:info:4503] [ 4503]   INFO: Starting ndmp for client [10.54.48.51].63556
0000001c.0002a6b7 050f8b29 Sat Sep 17 2016 20:25:02 +01:00 [kern_ndmpd:info:4503] [14875] DEBUG: NDMP Connect: Successfully connected to [10.54.48.51].63617, using local address [10.54.48.58].1035 (-0:00:01)
0000001c.0002a6b8 050f8b29 Sat Sep 17 2016 20:25:02 +01:00 [kern_ndmpd:info:4503] [14875] NOTICE: BASE_DATE '0' => L=0 T=0.0 level=0
0000001c.0002a6b9 050f8b29 Sat Sep 17 2016 20:25:02 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: START BACKUP Doing a LEVEL 0 backup

0000001c.0002a6bb 050f8b29 Sat Sep 17 2016 20:25:02 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: DATA: performing token full backup
0000001c.0002a6bc 050f8b29 Sat Sep 17 2016 20:25:03 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: DATA notification state 1 (SESS_STATE: LISTENING) event 10 (EVENT: STATE CHANGE) (-0:00:01)
0000001c.0002a6bd 050f8b29 Sat Sep 17 2016 20:25:03 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: DATA notification state 4 (SESS_STATE: ACTIVE) event 10 (EVENT: STATE CHANGE) (-0:00:01)
0000001c.0002a6be 050f8be5 Sat Sep 17 2016 20:25:22 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: buffer full for ndmp_io_process (fd=8) count total 35876 (5) (-0:00:01)
0000001c.0002a6bf 050f8c7b Sat Sep 17 2016 20:25:37 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: buffer full for ndmp_io_process (fd=8) count total 35876 (20) (-0:00:01)
0000001c.0002a6c0 050f8d15 Sat Sep 17 2016 20:25:51 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: buffer full for ndmp_io_process (fd=8) count total 35876 (35) (-0:00:01)
0000001c.0002a6c2 050f8da7 Sat Sep 17 2016 20:26:06 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: buffer full for ndmp_io_process (fd=8) count total 35876 (50) (-0:00:01)
0000001c.0002a6c3 050f8e40 Sat Sep 17 2016 20:26:22 +01:00 [kern_ndmpd:info:4503] [14875]   INFO: buffer full for ndmp_io_process (fd=8) count total 35876 (65) (-0:00:01)

Our media servers are able to connect to other filers over other networks, but this filer is on our new NGNI network which is the only one we are seeing these issues.

I was expecting switch port configuration because I was unable to telnet to the NDMP port on the filer from the same subnet as the media server and yet I am able to connect to the NDMP port from a server on the same subnet as the filer!?

Obviously from what has been posted previously it can't be that as they managed to backup a small amount of data, it seems to fail when open for a longer period.

I will let you know if I find anything out from our network team.

stevenro72 · ‎2016-09-23

By the way we are running NetApp Release 8.2.4P1 7-Mode