Restore Job Taking Longer than Usual

[Henson_D]

Good day Everyone,

Currently I have an issue about a restore that's now taking about 3hours+ which is longer than before as 1hour+. Can anyone teach me what are the best practices or tuning to be done to address the issue? 

Below is the log on BAR GUI that confuses me. Even if the files are restoring to different location.

16:53:26 (14631.001) Changed /db2/PRD/sapdata4/db2prd/NODE0000/PRD/T0000013/.SQLCRT.FLG to /sapdata4test/db2prd/NODE0000/PRD/T0000013/.SQLCRT.FLG

16:53:26 (14631.001) File /sapdata4test/db2prd/NODE0000/PRD/T0000013/.SQLCRT.FLG exists. Keeping it.

Thank you all in advance. Have a great day :)

Cheers!

Henson

[Marianne]

Have you had a look at the contents of /sapdata4test/db2prd/NODE0000/PRD/T0000013/?

According to the progress log, the file exists already. Maybe from a previous restore attempt?

To troubleshoot slow restore speed, take NBU out of the equation.
Find a file of +- 2GB on the media server and ftp to the same filesystem on the client.
What is the result?
 

To troubleshoot from NBU point of view, you need the following logs:

On media server: bptm and bpbrm

On client: tar
 

[Henson_D]

Thanks Marianne,

I don't see anything suspicious on the tar log. Below is the Detailed Status of the job. Do you have any idea of what the highlighted lines do?

4/2/2014 10:15:15 AM - begin Restore
4/2/2014 10:19:16 AM - restoring image PRODBCIA_1396016584
4/2/2014 10:19:16 AM - Info bprd(pid=11084) Restoring from copy 1 of image created 03/28/14 22:23:04    
4/2/2014 10:19:16 AM - requesting resource @aaaad
4/2/2014 10:19:16 AM - granted resource MediaID=@aaaad;DiskVolume=PureDiskVolume;DiskPool=smphhosyma02_dedupe_disk_pool;Path=PureDiskVolume;StorageServer=smphhosyma02.smprime.sm.ph;MediaServer=smphhosyma02.smprime.sm.ph
4/2/2014 10:19:17 AM - Info bpbrm(pid=1668) 10.246.198.200 is the host to restore to      
4/2/2014 10:19:17 AM - Info bpbrm(pid=1668) reading file list from client        
4/2/2014 10:19:22 AM - connecting
4/2/2014 10:19:22 AM - Info bpbrm(pid=1668) starting bptm           
4/2/2014 10:19:22 AM - Info tar32(pid=4450) Restore started           
4/2/2014 10:19:22 AM - connected; connect time: 00:00:00
4/2/2014 10:19:22 AM - Info bptm(pid=11556) start            
4/2/2014 10:19:22 AM - started process bptm (11556)
4/2/2014 10:19:22 AM - Info bpdm(pid=11556) reading backup image          
4/2/2014 10:19:23 AM - Info bptm(pid=11556) using 30 data buffers         
4/2/2014 10:19:23 AM - Info bptm(pid=11556) spawning a child process         
4/2/2014 10:19:23 AM - Info bptm(pid=11556) child pid: 9488          
4/2/2014 10:19:23 AM - Info bptm(pid=9488) start            
4/2/2014 10:19:23 AM - started process bptm (9488)
4/2/2014 10:19:25 AM - begin reading
4/2/2014 10:28:11 AM - Info bptm(pid=11556) waited for empty buffer 3248 times, delayed 3415 times    
4/2/2014 10:28:11 AM - end reading; read time: 00:08:46
4/2/2014 10:28:11 AM - begin reading
4/2/2014 10:36:34 AM - Info bptm(pid=11556) waited for empty buffer 3926 times, delayed 4106 times    
4/2/2014 10:36:34 AM - end reading; read time: 00:08:23
4/2/2014 10:36:35 AM - begin reading
4/2/2014 10:44:47 AM - Info bptm(pid=11556) waited for empty buffer 3956 times, delayed 4132 times    
4/2/2014 10:44:47 AM - end reading; read time: 00:08:12
4/2/2014 10:44:48 AM - begin reading
4/2/2014 10:53:17 AM - Info bptm(pid=11556) waited for empty buffer 3375 times, delayed 3592 times    
4/2/2014 10:53:17 AM - end reading; read time: 00:08:29
4/2/2014 10:53:17 AM - begin reading
4/2/2014 11:01:17 AM - Info bptm(pid=11556) waited for empty buffer 5275 times, delayed 5526 times    
4/2/2014 11:01:17 AM - end reading; read time: 00:08:00
4/2/2014 11:01:17 AM - begin reading
4/2/2014 11:09:05 AM - Info bptm(pid=11556) waited for empty buffer 6252 times, delayed 6629 times    
4/2/2014 11:09:05 AM - end reading; read time: 00:07:48
4/2/2014 11:09:05 AM - begin reading
4/2/2014 11:17:43 AM - Info bptm(pid=11556) waited for empty buffer 5628 times, delayed 6324 times    
4/2/2014 11:17:43 AM - end reading; read time: 00:08:38
4/2/2014 11:17:43 AM - begin reading
4/2/2014 11:54:53 AM - Info bptm(pid=11556) waited for empty buffer 18135 times, delayed 113638 times    
4/2/2014 11:54:53 AM - end reading; read time: 00:37:10
4/2/2014 11:54:53 AM - begin reading
4/2/2014 12:00:53 PM - Info bptm(pid=11556) waited for empty buffer 2477 times, delayed 8673 times    
4/2/2014 12:00:53 PM - begin reading
4/2/2014 12:04:59 PM - Info bptm(pid=11556) waited for empty buffer 1515 times, delayed 1629 times    
4/2/2014 12:04:59 PM - end reading; read time: 00:04:06
4/2/2014 12:05:00 PM - begin reading
4/2/2014 12:12:53 PM - Info bptm(pid=11556) waited for empty buffer 4478 times, delayed 4735 times    
4/2/2014 12:12:53 PM - end reading; read time: 00:07:53
4/2/2014 12:12:53 PM - begin reading
4/2/2014 12:20:40 PM - Info bptm(pid=11556) waited for empty buffer 4259 times, delayed 4467 times    
4/2/2014 12:20:40 PM - end reading; read time: 00:07:47
4/2/2014 12:20:41 PM - begin reading
4/2/2014 12:28:30 PM - Info bptm(pid=11556) waited for empty buffer 4459 times, delayed 4739 times    
4/2/2014 12:28:30 PM - end reading; read time: 00:07:49
4/2/2014 12:28:30 PM - begin reading
4/2/2014 12:36:23 PM - Info bptm(pid=11556) waited for empty buffer 3654 times, delayed 3850 times    
4/2/2014 12:36:23 PM - end reading; read time: 00:07:53
4/2/2014 12:36:23 PM - begin reading
4/2/2014 12:44:16 PM - Info bptm(pid=11556) waited for empty buffer 3794 times, delayed 4012 times    
4/2/2014 12:44:16 PM - end reading; read time: 00:07:53
4/2/2014 12:44:17 PM - begin reading
4/2/2014 12:52:05 PM - Info bptm(pid=11556) waited for empty buffer 4016 times, delayed 4239 times    
4/2/2014 12:52:05 PM - end reading; read time: 00:07:48
4/2/2014 12:52:05 PM - begin reading
4/2/2014 12:59:53 PM - Info bptm(pid=11556) waited for empty buffer 4516 times, delayed 4766 times    
4/2/2014 12:59:53 PM - end reading; read time: 00:07:48
4/2/2014 12:59:53 PM - begin reading
4/2/2014 1:07:48 PM - Info bptm(pid=11556) waited for empty buffer 4199 times, delayed 4416 times    
4/2/2014 1:07:48 PM - end reading; read time: 00:07:55
4/2/2014 1:07:48 PM - begin reading
4/2/2014 1:15:35 PM - Info bptm(pid=11556) waited for empty buffer 4903 times, delayed 5155 times    
4/2/2014 1:15:35 PM - end reading; read time: 00:07:47
4/2/2014 1:15:35 PM - begin reading
4/2/2014 1:23:40 PM - Info bptm(pid=11556) waited for empty buffer 3773 times, delayed 3958 times    
4/2/2014 1:23:40 PM - end reading; read time: 00:08:05
4/2/2014 1:23:40 PM - begin reading
4/2/2014 1:31:35 PM - Info bptm(pid=11556) waited for empty buffer 4242 times, delayed 4461 times    
4/2/2014 1:31:35 PM - end reading; read time: 00:07:55
4/2/2014 1:31:35 PM - begin reading
4/2/2014 1:39:25 PM - Info bptm(pid=11556) waited for empty buffer 4390 times, delayed 4672 times    
4/2/2014 1:39:25 PM - end reading; read time: 00:07:50
4/2/2014 1:39:25 PM - begin reading
4/2/2014 1:47:17 PM - Info bptm(pid=11556) waited for empty buffer 4749 times, delayed 5002 times    
4/2/2014 1:47:17 PM - end reading; read time: 00:07:52
4/2/2014 1:47:17 PM - begin reading
4/2/2014 1:55:03 PM - Info bptm(pid=11556) waited for empty buffer 4857 times, delayed 5098 times    
4/2/2014 1:55:03 PM - end reading; read time: 00:07:46
4/2/2014 1:55:03 PM - begin reading
4/2/2014 2:02:51 PM - Info bptm(pid=11556) waited for empty buffer 4843 times, delayed 5122 times    
4/2/2014 2:02:51 PM - end reading; read time: 00:07:48
4/2/2014 2:02:51 PM - begin reading
4/2/2014 2:10:44 PM - Info bptm(pid=11556) waited for empty buffer 4485 times, delayed 4761 times    
4/2/2014 2:10:44 PM - end reading; read time: 00:07:53
4/2/2014 2:10:44 PM - begin reading
4/2/2014 2:18:31 PM - Info bptm(pid=11556) waited for empty buffer 4971 times, delayed 5236 times    
4/2/2014 2:18:31 PM - end reading; read time: 00:07:47
4/2/2014 2:18:31 PM - begin reading
4/2/2014 2:26:20 PM - Info bptm(pid=11556) waited for empty buffer 4914 times, delayed 5161 times    
4/2/2014 2:26:20 PM - end reading; read time: 00:07:49
4/2/2014 2:26:20 PM - begin reading
4/2/2014 2:34:07 PM - Info bptm(pid=11556) waited for empty buffer 5006 times, delayed 5288 times    
4/2/2014 2:34:07 PM - end reading; read time: 00:07:47
4/2/2014 2:34:08 PM - begin reading
4/2/2014 2:41:55 PM - Info bptm(pid=11556) waited for empty buffer 5091 times, delayed 5383 times    
4/2/2014 2:41:55 PM - end reading; read time: 00:07:47
4/2/2014 2:41:55 PM - begin reading
4/2/2014 2:45:28 PM - Info bptm(pid=11556) waited for empty buffer 2105 times, delayed 2224 times    
4/2/2014 2:45:28 PM - begin reading
4/2/2014 2:45:30 PM - Info bptm(pid=11556) waited for empty buffer 0 times, delayed 0 times    
4/2/2014 2:45:30 PM - begin reading
4/2/2014 2:45:31 PM - Info bptm(pid=11556) waited for empty buffer 0 times, delayed 0 times    
4/2/2014 2:45:31 PM - begin reading
4/2/2014 2:45:32 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 13 times    
4/2/2014 2:45:32 PM - begin reading
4/2/2014 2:45:37 PM - Info bptm(pid=11556) waited for empty buffer 61 times, delayed 84 times    
4/2/2014 2:45:37 PM - begin reading
4/2/2014 2:45:38 PM - Info bptm(pid=11556) waited for empty buffer 0 times, delayed 0 times    
4/2/2014 2:45:38 PM - begin reading
4/2/2014 2:45:39 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 11 times    
4/2/2014 2:45:39 PM - begin reading
4/2/2014 2:45:40 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 29 times    
4/2/2014 2:45:40 PM - begin reading
4/2/2014 2:45:41 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 45 times    
4/2/2014 2:45:41 PM - begin reading
4/2/2014 2:45:42 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 45 times    
4/2/2014 2:45:42 PM - begin reading
4/2/2014 2:45:43 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 47 times    
4/2/2014 2:45:43 PM - begin reading
4/2/2014 2:45:48 PM - Info bptm(pid=11556) waited for empty buffer 64 times, delayed 66 times    
4/2/2014 2:45:48 PM - begin reading
4/2/2014 2:45:49 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 2 times    
4/2/2014 2:45:49 PM - begin reading
4/2/2014 2:45:50 PM - Info bptm(pid=11556) waited for empty buffer 1 times, delayed 32 times    
4/2/2014 2:45:50 PM - begin reading
4/2/2014 2:52:48 PM - Info bptm(pid=11556) waited for empty buffer 3087 times, delayed 3179 times    
4/2/2014 2:52:48 PM - end reading; read time: 00:06:58
4/2/2014 2:52:49 PM - begin reading
4/2/2014 3:00:27 PM - Info bptm(pid=11556) waited for empty buffer 4353 times, delayed 4400 times    
4/2/2014 3:00:27 PM - end reading; read time: 00:07:38
4/2/2014 3:00:28 PM - begin reading
4/2/2014 3:08:11 PM - Info bptm(pid=11556) waited for empty buffer 4658 times, delayed 4765 times    
4/2/2014 3:08:11 PM - end reading; read time: 00:07:43
4/2/2014 3:08:12 PM - begin reading
4/2/2014 3:15:49 PM - Info bptm(pid=11556) waited for empty buffer 4781 times, delayed 4852 times    
4/2/2014 3:15:49 PM - end reading; read time: 00:07:37
4/2/2014 3:15:49 PM - begin reading
4/2/2014 3:23:29 PM - Info bptm(pid=11556) waited for empty buffer 4513 times, delayed 4576 times    
4/2/2014 3:23:29 PM - end reading; read time: 00:07:40
4/2/2014 3:23:30 PM - begin reading
4/2/2014 3:31:23 PM - Info bptm(pid=11556) waited for empty buffer 3498 times, delayed 3550 times    
4/2/2014 3:31:23 PM - end reading; read time: 00:07:53
4/2/2014 3:31:23 PM - begin reading
4/2/2014 3:39:15 PM - Info bptm(pid=11556) waited for empty buffer 3669 times, delayed 3762 times    
4/2/2014 3:39:15 PM - end reading; read time: 00:07:52
4/2/2014 3:39:15 PM - begin reading
4/2/2014 3:46:58 PM - Info bptm(pid=11556) waited for empty buffer 3974 times, delayed 4026 times    
4/2/2014 3:46:58 PM - end reading; read time: 00:07:43
4/2/2014 3:46:59 PM - begin reading
4/2/2014 3:54:37 PM - Info bptm(pid=11556) waited for empty buffer 4532 times, delayed 4623 times    
4/2/2014 3:54:37 PM - end reading; read time: 00:07:38
4/2/2014 3:54:38 PM - begin reading
4/2/2014 4:02:16 PM - Info bptm(pid=11556) waited for empty buffer 4388 times, delayed 4463 times    
4/2/2014 4:02:16 PM - end reading; read time: 00:07:38
4/2/2014 4:02:16 PM - begin reading
4/2/2014 4:09:58 PM - Info bptm(pid=11556) waited for empty buffer 4194 times, delayed 4308 times    
4/2/2014 4:09:58 PM - end reading; read time: 00:07:42
4/2/2014 4:09:58 PM - begin reading
4/2/2014 4:17:39 PM - Info bptm(pid=11556) waited for empty buffer 3907 times, delayed 3967 times    
4/2/2014 4:17:39 PM - end reading; read time: 00:07:41
4/2/2014 4:17:40 PM - begin reading
4/2/2014 4:25:18 PM - Info bptm(pid=11556) waited for empty buffer 4619 times, delayed 4678 times    
4/2/2014 4:25:18 PM - end reading; read time: 00:07:38
4/2/2014 4:25:18 PM - begin reading
4/2/2014 4:33:02 PM - Info bptm(pid=11556) waited for empty buffer 4145 times, delayed 4225 times    
4/2/2014 4:33:02 PM - end reading; read time: 00:07:44
4/2/2014 4:33:03 PM - begin reading
4/2/2014 4:40:43 PM - Info bptm(pid=11556) waited for empty buffer 4598 times, delayed 4694 times    
4/2/2014 4:40:43 PM - end reading; read time: 00:07:40
4/2/2014 4:40:43 PM - begin reading
4/2/2014 4:48:43 PM - Info bptm(pid=11556) waited for empty buffer 3586 times, delayed 3675 times    
4/2/2014 4:48:43 PM - end reading; read time: 00:08:00
4/2/2014 4:48:43 PM - begin reading
4/2/2014 4:56:39 PM - Info bptm(pid=11556) waited for empty buffer 3556 times, delayed 3609 times    
4/2/2014 4:56:39 PM - end reading; read time: 00:07:56
4/2/2014 4:56:39 PM - begin reading
4/2/2014 5:04:36 PM - Info bptm(pid=11556) waited for empty buffer 3498 times, delayed 3601 times    
4/2/2014 5:04:36 PM - end reading; read time: 00:07:57
4/2/2014 5:04:37 PM - begin reading
4/2/2014 5:12:17 PM - Info bptm(pid=11556) waited for empty buffer 4179 times, delayed 4266 times    
4/2/2014 5:12:17 PM - end reading; read time: 00:07:40
4/2/2014 5:12:18 PM - begin reading
4/2/2014 5:20:03 PM - Info bptm(pid=11556) waited for empty buffer 3547 times, delayed 3599 times    
4/2/2014 5:20:03 PM - end reading; read time: 00:07:45
4/2/2014 5:20:03 PM - begin reading
4/2/2014 5:27:50 PM - Info bptm(pid=11556) waited for empty buffer 3050 times, delayed 3089 times    
4/2/2014 5:27:50 PM - end reading; read time: 00:07:47
4/2/2014 5:27:51 PM - begin reading
4/2/2014 5:28:26 PM - Info bptm(pid=11556) waited for empty buffer 413 times, delayed 456 times    
4/2/2014 5:28:26 PM - begin reading
4/2/2014 5:57:09 PM - Info bptm(pid=11556) waited for empty buffer 12647 times, delayed 82361 times    
4/2/2014 5:57:09 PM - end reading; read time: 00:28:43
4/2/2014 5:57:10 PM - begin reading
4/2/2014 6:11:25 PM - Info bptm(pid=11556) waited for empty buffer 6559 times, delayed 40722 times    
4/2/2014 6:11:25 PM - end reading; read time: 00:14:15
4/2/2014 6:11:25 PM - Info tar32(pid=4450) done. status 0          
4/2/2014 6:11:25 PM - Info tar32(pid=4450) done. status: 0          
4/2/2014 6:11:26 PM - Info bptm(pid=11556) completed reading backup image         
4/2/2014 6:11:26 PM - Info bptm(pid=11556) EXITING with status 0 <----------        
4/2/2014 6:11:26 PM - Info smphhosyma02.smprime.sm.ph(pid=11556) StorageServer=PureDisk:smphhosyma02.smprime.sm.ph; Report=PDDO Stats for (smphhosyma02.smprime.sm.ph): read: 2649724028 KB, CR received: 2651501147 KB, CR received over FC: 0 KB, dedup: 0.0%
4/2/2014 6:11:26 PM - Info tar32(pid=4450) done. status: 0: the requested operation was successfully completed    
4/2/2014 6:11:27 PM - restored image PRODBCIA_1396016584 - (the requested operation was successfully completed(0)); restore time 07:52:11
4/2/2014 6:11:27 PM - end Restore; elapsed time: 07:56:12
the requested operation was successfully completed(0)

Thanks in advance. Have a great day. :)

Cheers!

Henson

[Marianne]

... waited for empty buffer xxxxx times, delayed xxxx times....

We need bptm log to see data and network buffer sizes.

The above indicates that data is read fast enough, but there is either slow network transfer rate between media server and client or slow write speed on the destination disk on the client.

You may want to take NBU out of the picture and ftp +- 2GB data file from media server to client. What is the transfer rate? Ftp to more than one filesystem on client. Is there a difference?

[Henson_D]

Thanks for that Marianne. Will attached the bptm log once I have it.