1. Welcome Guest! In order to create a new topic or reply to an existing one, you must register first. It is easy and free. Click here to sign up now!.
    Dismiss Notice

EMC Retrospect backup very slow after installing Vista SP2

Discussion in 'Windows Vista' started by Mike Turner, Jun 15, 2009.

  1. Mike Turner

    Mike Turner Guest

    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.
     
    Mike Turner, Jun 15, 2009
    #1
  3. MGBassace

    MGBassace Guest

    "Mike Turner" wrote:
    <!--coloro:blue--><span style="color:blue <!--/coloro-->
    > 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:Windowsinf 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.<!--colorc--><!--/colorc-->



    Dont know about the infcache.1 file, Are you performing a normal or recycled
    backup?
     
    MGBassace, Jun 15, 2009
    #2
  4. Mike Turner

    Mike Turner Guest

    "MGBassace" wrote:
    <!--coloro:blue--><span style="color:blue <!--/coloro-->
    >
    >
    > "Mike Turner" wrote:
    > <!--coloro:green--><span style="color:green <!--/coloro-->
    > > 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:Windowsinf 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.<!--colorc--><!--/colorc-->
    >
    >
    >
    > Dont know about the infcache.1 file, Are you performing a normal or recycled
    > backup?<!--colorc--><!--/colorc-->

    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, Jun 15, 2009
    #3
  5. Mike Turner

    Mike Turner Guest

    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:-

    <!--coloro:blue--><span style="color:blue <!--/coloro--><!--coloro:green--><span style="color:green <!--/coloro--><!--coloro:darkred--><span style="color:darkred <!--/coloro-->
    >>> [Build Driver List - 1394SEAGATE&ATA_DEVICE_004301000000372000]
    >>> Section start 2009/05/17 21:09:38.652<!--colorc--><!--/colorc--><!--colorc--><!--/colorc--><!--colorc--><!--/colorc-->
    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:-

    <!--coloro:blue--><span style="color:blue <!--/coloro--><!--coloro:green--><span style="color:green <!--/coloro--><!--coloro:darkred--><span style="color:darkred <!--/coloro-->
    >>> [Build Driver List - 1394SEAGATE&ATA_DEVICE_004301000000372000]
    >>> Section start 2009/06/16 07:43:05.417<!--colorc--><!--/colorc--><!--colorc--><!--/colorc--><!--colorc--><!--/colorc-->
    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]

    <!--coloro:blue--><span style="color:blue <!--/coloro--><!--coloro:green--><span style="color:green <!--/coloro--><!--coloro:darkred--><span style="color:darkred <!--/coloro-->
    >>> [Build Driver List - 1394WD&MY_BOOKFC84A13AB5A99000]
    >>> Section start 2009/06/16 07:43:48.177<!--colorc--><!--/colorc--><!--colorc--><!--/colorc--><!--colorc--><!--/colorc-->
    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 :-


    <!--coloro:blue--><span style="color:blue <!--/coloro--><!--coloro:green--><span style="color:green <!--/coloro--><!--coloro:darkred--><span style="color:darkred <!--/coloro-->
    >>> [Build Driver List - 1394SEAGATE&ATA_DEVICE_004301000000372000]
    >>> Section start 2009/06/16 12:00:23.047<!--colorc--><!--/colorc--><!--colorc--><!--/colorc--><!--colorc--><!--/colorc-->
    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]

    <!--coloro:blue--><span style="color:blue <!--/coloro--><!--coloro:green--><span style="color:green <!--/coloro--><!--coloro:darkred--><span style="color:darkred <!--/coloro-->
    >>> [Build Driver List - 1394WD&MY_BOOKFC84A13AB5A99000]
    >>> Section start 2009/06/16 12:00:54.684<!--colorc--><!--/colorc--><!--colorc--><!--/colorc--><!--colorc--><!--/colorc-->
    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.
     
    Mike Turner, Jun 16, 2009
    #4

Share This Page