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.
