EMC Retrospect backup very slow after installing Vista SP2

[Mike Turner]

I use EMC Retrospect Professional to backup my PC to an external hard drive
automatically every night. Under Vista SP1, it used to take about 20 minutes.
Since installing Vista SP2, it takes about 4 hours 20 minutes. The extra time
is in a stage that it calls "Building a Snapshot" for my C: drive. During
this time, I have noticed that the Date Modified of the .PNF files in
C:\Windows\inf is constantly updating, as is the infcache.1 file.

I have tried releasing the infcache.1 file. This does not cure the problem,
but causes other difficulties, so I have reinstated the original.

 

[MGBassace]

I use EMC Retrospect Professional to backup my PC to an external hard drive
automatically every night. Under Vista SP1, it used to take about 20 minutes.
Since installing Vista SP2, it takes about 4 hours 20 minutes. The extra time
is in a stage that it calls "Building a Snapshot" for my C: drive. During
this time, I have noticed that the Date Modified of the .PNF files in
C:\Windows\inf is constantly updating, as is the infcache.1 file.

I have tried releasing the infcache.1 file. This does not cure the problem,
but causes other difficulties, so I have reinstated the original.

Dont know about the infcache.1 file, Are you performing a normal or recycled
backup?

 

[Mike Turner]

Dont know about the infcache.1 file, Are you performing a normal or recycled
backup?

It is a normal backup. I have raised it with EMC, but had no reply.

I am convinced that there is a connection with what is happening with the
INFCACHE.1 file.

 

[Mike Turner]

I have drawn together some log files to show why I think that this problem is
associated with INFCACHE.1.

Here is an entry from the Retrospect log showing a scheduled backup before
installing SP2. You can see that the
time from starting to copy the C: drive to finishing storing the snapshot is
about 13 minutes.


+ Normal backup using Disc Backup at 17/04/2009 21:00
To Backup Set Disk Backup...

- 17/04/2009 21:00:26: Copying System Disc (C
17/04/2009 21:13:19: Snapshot stored, 188.5 MB
17/04/2009 21:13:34: Comparing System Disc (C
17/04/2009 21:14:44: Execution completed successfully
Completed: 616 files, 855.1 MB, with 65% compression
Performance: 765.7 MB/minute (801.5 copy, 743.5 compare)
Duration: 00:14:18 (00:12:03 idle/loading/preparing)


- 17/04/2009 21:14:45: Copying Applications (D
17/04/2009 21:16:53: Snapshot stored, 14.4 MB
17/04/2009 21:16:57: Comparing Applications (D
17/04/2009 21:17:03: Execution completed successfully
Completed: 201 files, 9,771 KB, with 56% compression
Performance: 104.0 MB/minute (114.5 copy, 95.4 compare)
Duration: 00:02:18 (00:02:07 idle/loading/preparing)


- 17/04/2009 21:17:03: Copying Data (E
17/04/2009 21:17:29: Snapshot stored, 2,279 KB
17/04/2009 21:17:32: Comparing Data (E
17/04/2009 21:17:41: Execution completed successfully
Completed: 214 files, 55.1 MB, with 58% compression
Performance: 412.8 MB/minute (412.8 copy, 412.8 compare)
Duration: 00:00:37 (00:00:20 idle/loading/preparing)


- 17/04/2009 21:17:41: Copying Temporary Files (F
17/04/2009 21:17:54: Snapshot stored, 477 KB
17/04/2009 21:17:58: Comparing Temporary Files (F
17/04/2009 21:18:05: Execution completed successfully
Completed: 94 files, 21.1 MB, with 41% compression
Performance: 230.1 MB/minute (421.9 copy, 180.8 compare)
Duration: 00:00:23 (00:00:12 idle/loading/preparing)


- 17/04/2009 21:18:05: Copying Photographs (G
17/04/2009 21:18:05: No files need to be copied
17/04/2009 21:18:23: Snapshot stored, 2,259 KB
17/04/2009 21:18:26: Comparing Photographs (G
17/04/2009 21:18:29: Execution completed successfully
Duration: 00:00:23 (00:00:19 idle/loading/preparing)

17/04/2009 21:18:34: Execution completed successfully
Total performance: 634.1 MB/minute with 64% compression
Total duration: 00:18:01 (00:15:04 idle/loading/preparing)


During this time, the setupapi.app.log had lots of entries like the
following:-

[Build Driver List - 1394\SEAGATE&ATA_DEVICE_00\4301000000372000]
Section start 2009/05/17 21:09:38.652

cmd: Launcher hide_ui
dvi: Searching for hardware ID(s):
dvi: 1394\seagate&ata_device_00
dvi: Searching for compatible ID(s):
dvi: 1394\609e&10483
dvi: 1394\609e&1
dvi: 1394\609e
dvi: Enumerating INFs from path list 'C:\Windows\inf'
inf: Opened PNF:
'C:\Windows\System32\DriverStore\FileRepository\sbp2.inf_0e22c55c\sbp2.inf'
([strings.0409] <src=drvstore>)
dvi: Created Driver Node:
dvi: HardwareID - 1394\609E&10483
dvi: InfName -
C:\Windows\System32\DriverStore\FileRepository\sbp2.inf_0e22c55c\sbp2.inf
dvi: DevDesc - SBP2 Compliant IEEE 1394 device
dvi: DrvDesc - SBP2 Compliant IEEE 1394 device
dvi: Provider - Microsoft
dvi: Mfg - IEEE 1394 SBP-2 Device Vendor
dvi: ModelsSec - sbp2_device.NTx86
dvi: InstallSec - sbp2_install
dvi: ActualSec - sbp2_install
dvi: Rank - 0x0dff2000
dvi: Signer - microsoft windows
dvi: Signer Score - INBOX
dvi: DrvDate - 06/21/2006
dvi: Version - 6.0.6001.18000
inf: Searched 1 potential matches in published INF directory
inf: Searched 34 INFs in directory: 'C:\Windows\inf'
<<< Section end 2009/05/17 21:09:40.602
<<< [Exit status: SUCCESS]



I believe that Retrospect uses the command "Launcher hide_ui" to launch
scheduled tasks.

A log from a scheduled backup after installing SP2 is like this:-


+ Normal backup using Disc Backup at 16/06/2009 07:31
To Backup Set Disk Backup...

- 16/06/2009 07:31:12: Copying System Disc (C
16/06/2009 11:29:30: Snapshot stored, 189.8 MB
16/06/2009 11:30:32: Comparing System Disc (C
16/06/2009 11:33:40: Execution completed successfully
Completed: 1140 files, 819.9 MB, with 55% compression
Performance: 220.5 MB/minute (190.6 copy, 261.6 compare)
Duration: 04:02:27 (03:55:01 idle/loading/preparing)


- 16/06/2009 11:33:40: Copying Applications (D
16/06/2009 11:36:03: Snapshot stored, 14.9 MB
16/06/2009 11:36:07: Comparing Applications (D
16/06/2009 11:36:17: Execution completed successfully
Completed: 199 files, 7,022 KB, with 75% compression
Performance: 51.4 MB/minute (68.5 copy, 41.1 compare)
Duration: 00:02:36 (00:02:20 idle/loading/preparing)


- 16/06/2009 11:36:17: Copying Data (E
16/06/2009 11:36:50: Snapshot stored, 2,293 KB
16/06/2009 11:36:54: Comparing Data (E
16/06/2009 11:37:11: Execution completed successfully
Completed: 228 files, 65.3 MB, with 65% compression
Performance: 244.8 MB/minute (261.1 copy, 244.8 compare)
Duration: 00:00:53 (00:00:21 idle/loading/preparing)


- 16/06/2009 11:37:11: Copying Temporary Files (F
16/06/2009 11:37:31: Snapshot stored, 430 KB
16/06/2009 11:37:34: Comparing Temporary Files (F
16/06/2009 11:37:46: Execution completed successfully
Completed: 84 files, 53.5 MB, with 0% compression
Performance: 305.4 MB/minute (356.3 copy, 291.5 compare)
Duration: 00:00:35 (00:00:14 idle/loading/preparing)


- 16/06/2009 11:37:46: Copying Photographs (G
16/06/2009 11:37:46: No files need to be copied
16/06/2009 11:38:01: Snapshot stored, 2,265 KB
16/06/2009 11:38:05: Comparing Photographs (G
16/06/2009 11:38:07: Execution completed successfully
Duration: 00:00:21 (00:00:16 idle/loading/preparing)

16/06/2009 11:38:13: Execution completed successfully
Total performance: 217.7 MB/minute with 51% compression
Total duration: 04:06:47 (03:58:14 idle/loading/preparing)

showing the snapshot phase taking about 4 hours.

The setupapi.app.log has entries including:-

[Build Driver List - 1394\SEAGATE&ATA_DEVICE_00\4301000000372000]
Section start 2009/06/16 07:43:05.417

cmd: Launcher hide_ui
! inf: Detected INFCACHE inconsistency
! inf: Attempting INFCACHE repair 07:43:05.542
! inf: Verify/Fix on INFCACHE complete, status(4) - Fixed 07:43:44.713
<<< Section end 2009/06/16 07:43:48.177
<<< [Exit status: SUCCESS]

[Build Driver List - 1394\WD&MY_BOOK\FC84A13AB5A99000]
Section start 2009/06/16 07:43:48.177

cmd: Launcher hide_ui
! inf: Detected INFCACHE inconsistency
! inf: Attempting INFCACHE repair 07:43:48.177
! inf: Verify/Fix on INFCACHE complete, status(4) - Fixed 07:43:59.143
<<< Section end 2009/06/16 07:44:00.844
<<< [Exit status: SUCCESS]

If, however, I run the backup manually, I get a log such as this:-


+ Normal backup using Disc Backup at 16/06/2009 11:52
To Backup Set Disk Backup...

- 16/06/2009 11:52:52: Copying System Disc (C
16/06/2009 12:30:46: Snapshot stored, 190.0 MB
16/06/2009 12:31:37: Comparing System Disc (C
16/06/2009 12:33:05: Execution completed successfully
Completed: 891 files, 621.1 MB, with 53% compression
Performance: 468.6 MB/minute (517.5 copy, 428.2 compare)
Duration: 00:40:12 (00:37:32 idle/loading/preparing)


- 16/06/2009 12:33:05: Copying Applications (D
16/06/2009 12:35:21: Snapshot stored, 14.9 MB
16/06/2009 12:35:25: Comparing Applications (D
16/06/2009 12:35:34: Execution completed successfully
Completed: 7 files, 3,803 KB, with 55% compression
Performance: 40.5 MB/minute (74.2 copy, 27.8 compare)
Duration: 00:02:29 (00:02:17 idle/loading/preparing)


- 16/06/2009 12:35:34: Copying Data (E
16/06/2009 12:35:58: Snapshot stored, 2,293 KB
16/06/2009 12:36:02: Comparing Data (E
16/06/2009 12:36:13: Execution completed successfully
Completed: 190 files, 34.4 MB, with 58% compression
Performance: 242.5 MB/minute (343.6 copy, 206.1 compare)
Duration: 00:00:39 (00:00:21 idle/loading/preparing)


- 16/06/2009 12:36:13: Copying Temporary Files (F
16/06/2009 12:36:25: Snapshot stored, 429 KB
16/06/2009 12:36:29: Comparing Temporary Files (F
16/06/2009 12:36:37: Execution completed successfully
Completed: 16 files, 9,702 KB, with 76% compression
Performance: 113.6 MB/minute (568.4 copy, 71.0 compare)
Duration: 00:00:23 (00:00:13 idle/loading/preparing)


- 16/06/2009 12:36:37: Copying Photographs (G
16/06/2009 12:36:37: No files need to be copied
16/06/2009 12:36:56: Snapshot stored, 2,266 KB
16/06/2009 12:36:59: Comparing Photographs (G
16/06/2009 12:37:04: Execution completed successfully
Duration: 00:00:26 (00:00:19 idle/loading/preparing)

16/06/2009 12:37:10: Execution completed successfully
Total performance: 389.4 MB/minute with 53% compression
Total duration: 00:44:11 (00:40:45 idle/loading/preparing)

and entries in the setupapi.app.log such as :-

[Build Driver List - 1394\SEAGATE&ATA_DEVICE_00\4301000000372000]
Section start 2009/06/16 12:00:23.047

cmd: "D:\Program Files\Retrospect\Retrospect 7.6\Retrospect.exe"
! inf: Detected INFCACHE inconsistency
!!! inf: Error searching published INFs - likely system corruption!
!!! inf: Error 13: The data is invalid.
<<< Section end 2009/06/16 12:00:54.668
<<< [Exit status: SUCCESS]

[Build Driver List - 1394\WD&MY_BOOK\FC84A13AB5A99000]
Section start 2009/06/16 12:00:54.684

cmd: "D:\Program Files\Retrospect\Retrospect 7.6\Retrospect.exe"
! inf: Detected INFCACHE inconsistency
!!! inf: Error searching published INFs - likely system corruption!
!!! inf: Error 13: The data is invalid.
<<< Section end 2009/06/16 12:00:55.604
<<< [Exit status: SUCCESS]

I think that the main difference between a scheduled backup and a manual
backup is that a scheduled backup runs as SYSTEM
but a manual backup runs as the currently logged in user.