Shortcuts remain in pending state

[pL0ck]

Hi All

I have been digging into a problem for some time now in the hope of finding a solution, but sadly not getting too far. Our setup is Enterprise Vault 10.0.4CH3 running across 6 Exchange servers utilising 6 Vault stores (one for each). A number of users reported that items would remain as shortcuts even after the backup had successfully run. We have safety copies enabled so items remain pending until backup completes and the archive bit reset.

Looking at the users involved they appear to be on a particular vault store. Mine for instance works fine and items get archived after 60days and once the backup runs the safety copy is turned into a proper shortcut. These users, and I'm not sure if it everyone on that particular vault store, they get the pending item as the archive runs between 6PM and 12AM, but when the backup successfully runs at in the morning, the items remains pending. We have a script that puts the vault stores in backup at 3AM and takes them out of backup mode at 7AM as the backup starts after 3AM.

The items then reset back to message status after 3 days or so.

What I'm trying to find out is what triggers or what task is involved in turning the pending item to a shortcut? I think I read somewhere that taking the vault stores out of backup mode will trigger it? Does the next run of the archive process the change? If so I have already manually run these on selected mailboxes without any luck. I've DTraced the archive task as well, but can't see it trying to change the items from pending.

Any help would be greatly appreciated.

Cheers

Peter 

[Rob_Wilcox1]

The StorageFileWatch process is responsible for turning pending items into full shortcuts

[ChayDouglas]

Hi Peter,

In the properties of the partitions of the affected Vault Store, on the backup tab - what does it say under the status section?

As soon as items are registered as secured, they will start the process of changing to shortcuts...

If there hasn't been a secured item in a while, ensure that the archive bit is being removed from the files with the backup procedure.

If the items are being secured, it may be an issue with the archiving task and its associated MSMQs - particularly A1.

If you can check the secured item status first though...

Cheers
Chay



 

[pL0ck]

Hi Rob

Thank you for the info. I wanted to know wha triggered the StorageFileWatch to begin processing. Based on some of the articles I have read it is when the vaults come out of backup mode. Is it possible to trigger a StorageFileWatch on a single mailbox and DTrace it?

Chay: The details on the secured items all looks good and reports show pretty much 0 outstanding items to backup each morning (see attachment).

I'm now thinking it may be an indexing issue based on articles on how the entire process works. Not sure as I'm also not seeing any issues either with index reports, but the affected users have reported that they cannot search and find items that are still in pending state. I'm going to look a bit deeper into that today.

Cheers

Peter

[Rob_Wilcox1]

Yes, I think it's when the partition/vault store comes out of backup mode. It doesn't operate on a per-mailbox basis though..

[Ben_Watts]

Rob is correct, it is when the VS comes out of Backup Mode and/or when the Storage Service, which is responsible for that VS, is started/restarted.

My first point of call would be SQL to see if we are even registering these items as items to check when we come out of Backup Mode, run the below against the VS that is having problems, it will give you a list of files to check for validity and to see if the Archive Bit has been removed or not:-

SELECT 
ItemName
, ItemSecured
FROM WatchFile
WHERE ItemSecured = 0

If the above returns 0 results then that is why we arent flipping the items from Pending to Fully archived, EV will only process the items in this table when we come ouf of Backup Mode.

If you get results check the files themselves to ensure the Archive bit has been removed from them correctly.

Then if you have all items in there from 'yesterday's' archive run that are clear of the Archive bit bit are still shown as Pending in users Mailboxes simply start a Dtrace of the StorageFileWatch process, place that VS into Backup Mode and take it out of backup mode, this should then capture all the files we are hitting, and checking, and highlight any potential issues.

Archiving and Indexing are completely seperate so to speak as much as they do usually happen at the same time.

You can Archive successfully and fail to Index items completely and we will still flip the Pending items to fully archived so long as the backup process has been completed correctly and the Archive Bit or Trigger file actions have been carried out, so I wouldn't get caught up in the Indexing side of things too much.

There are things that can go wrong during the Archiving process which may cause the issues you are seeing but to be honest, going into that, you would be better off raising a support call as it involves investigating the SQL side of things a lot more.

[ChayDouglas]

It looks like the last secured item was 3 days ago, so we should be seeing pending items from the last 3 days of your archiving policy (6 months?) and all shortcuts older than that in mailboxes.

If there are shortcuts or normal items older than that in Outlook, I would check the MSMQs.

Are there items in the A1 queue?

What happens if you do a run now of the archiving task for shortcut processing only?

Cheers
Chay
https://www.mirrorsphere.com/enterprise-vault-services/

[pL0ck]

Hi Ben

Thank you for the reply. I had actually been down checking the WatchFile table and found there are no entries in there, but there are no entries for any of the 6 vault stores. I think as it archives between 6PM and midnight, and then backs up at 3AM to 7AM it is done and dusted by the time I get in to check.

I'll look at doing a manual archive run on one of the mailboxes and see if the WatchFile table registers new items. We have about 2,500 users per vault store so I am trying to see if this issue is vault store wide or selected mailboxes. I have heard from one of the support guys here, that it is users from 2 of the vault stores both of which are controlled by 1 EV server (6 Exchange servers, 6 mailbox databases, 1 EV server per 2 Exchange servers). I need to verify that though :)

Good to hear that indexing doesn't prevent the flip. Should the items be searchable though of they are still in pending? Users have complained that they cannot find any item (via Search or Archive Explorer) that is pending.

Cheers

Peter

[Ben_Watts]

Not a problem at all.

If they havent been archived/indexed correctly then no they wont be searchable.

If the items are not in the Watchfile table but ARE still Pending in users mailboxes I would assume, at this point in time, something went wrong with the Archive process and as such we wouldnt have gotten around to the Indexing side of things therefore it explains the inability to find the items that are Pending.

I have seen it previously where we attempt to archive items, hit an issue (for one reason or another), that halts the archiving process for those items, we then revert the archive action (removing entries from SQL tables etc) but are not in a situation (again for one reason or another) where we can revert the items back from Pending to normal IPM.Note items, we should be throwing errors during the Archiving run for these items to state that fact, if not in the Event logs it will be captured/capturable in the Dtrace.

If you find yourself in that situation I would Dtrace the ArchiveTask process during a Manual Archive run on a single mailbox if you can reliably reproduce the situation and find out what is happening at that point in time. If you are unable to reproduce it during Manual Archiving then we would need to look into that a bit more.

[Ben_Watts]

One other thing to check is the JournalArchive table, see if that has any items in it that are 'BackupComplete = 0'

Sometimes the items are in there but not in the Watchfile table, not very common and not really a great situation to be in but needs checking.

[pL0ck]

Hi Ben

So yesterday I saw the WatchFile table filling up, although difficult to determine mailboxes from the entries and an import was running at the same time. Anyway this morning the table was empty so it looks like it is being updated correctly pre and post backup.

With the table empty I did a RunNow on one of the mailboxes affected. No entries appeared in the WatchFile table despite the event log saying an additional 49 items archived. So I did the same on my mailbox which I know works and it did add entries for 95 new archived items.

I waited a while and fired up DTrace on the ArchiveTask and then ran the run now again on the dodgy mailbox. The Archive task definately flagged the items as pending as you can see via the before/after screenshots,

and the DTrace log seems to indicate archive elegibility but nothing appears in WatchFile so presumably this woould prevent it being turned into a proper shortcut when StorageFileWatch runs.

322502119 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {GetCalculatedModifiedDate:#1203} Calculated date (dd/mm/yyyy): [28/10/2014 22:42.52] [PR_MESSAGE_DELIVERY_TIME]
322502120 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L :CArchivingAgent::IsEligibleForArchive(/o=IMMI/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=PRAMUH35f) |The message titled: RE: Thanks for a job well done [SEC=UNCLASSIFIED] has the retention category of its parent folder its value  is 189E475016881914F924E2E5675D9D6891b10000evserver1   |
322502121 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L :CArchivingAgent::IsEligibleForArchive(/o=IMMI/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=PRAMUH35f) |The message titled: RE: Thanks for a job well done [SEC=UNCLASSIFIED] is eligible for archive  |
322502122 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
322502123 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M {CArchivingAgent::GetFolderPathForSavesetExchangeLocation:#5749} folder path to store [Inbox]
322502124 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CArchivingAgent::QueueEligibleItem:#24955} Eligible Item Strategy [Age]
322502125 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx} (Entry)
322502126 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData} (Entry)
322502127 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData}|Vault ID: 1C15CA8BF6E0C6844922F9523A03825D01110000evserver1|Status: 1|Limit Status: 0|Storage Svc: 17E3618165863464BA8E087E843340A4E1e10000evserver1|Rollover Vault :|Vault Store Status: 0
322502128 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData} (Exit) Status: [Success]
322502129 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus} (Entry)
322502130 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus:#1146} Storage Service [17E3618165863464BA8E087E843340A4E1e10000evserver1] throttle status: [DV_DS_AS_AVAILABLE (1)].
322502131 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus} (Exit) Status: [Success]
322502132 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx:#759} The throttle status for archive [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] is unchanged: [DV_DS_AS_AVAILABLE (1)].
322502133 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData} (Entry)
322502134 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData:#1225} Vault [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] status: [DV_DS_AS_AVAILABLE (1)]
322502135 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData} (Exit) Status: [Success]
322502136 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx:#793} Checked Storage information, and the throttle status for archive [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] is still [DV_DS_AS_AVAILABLE (1)].
322502137 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx} (Exit) Status: [Success]
322502138 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::ReserveQualifyingPosition:#199} bQualifyByAge[True] m_archivingstrategy[1]
322502139 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CPrioritizedItemTable::GetQualifyingPosition:#249} (Age) - Qualified to enter list
322502140 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::ReserveQualifyingPosition:#221} m_StandingQualifiedList[1] iCallerToken[30031]
322502141 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CPrioritizedItemTable::InsertRow:#283} (Age) - Inserting a new row
322502142 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::InsertItem:#166} insert age table item
322502143 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
322502144 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {MigratedDominoItems::IsMigratedDominoShortcut} (Entry)
322502145 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {PropsItem::HasShortcutProps:#149} Shortcut properties are not present (incorrect MAPI type; expecting PT_STRING8).
322502146 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {MigratedDominoItems::IsMigratedDominoShortcut:#198} Missing shortcut properties that are indicative of a migrated Domino shortcut.
322502147 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {MigratedDominoItems::IsMigratedDominoShortcut} (Exit) Status: [Success]
322502148 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {GetCalculatedModifiedDate:#1203} Calculated date (dd/mm/yyyy): [28/10/2014 22:40.41] [PR_MESSAGE_DELIVERY_TIME]
322502149 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L :CArchivingAgent::IsEligibleForArchive(/o=IMMI/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=PRAMUH35f) |The message titled: Thanks for a job well done [SEC=UNCLASSIFIED] has the retention category of its parent folder its value  is 189E475016881914F924E2E5675D9D6891b10000evserver1   |
322502150 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L :CArchivingAgent::IsEligibleForArchive(/o=IMMI/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=PRAMUH35f) |The message titled: Thanks for a job well done [SEC=UNCLASSIFIED] is eligible for archive  |
322502151 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
322502152 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M {CArchivingAgent::GetFolderPathForSavesetExchangeLocation:#5749} folder path to store [Inbox]
322502153 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CArchivingAgent::QueueEligibleItem:#24955} Eligible Item Strategy [Age]
322502154 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx} (Entry)
322502155 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData} (Entry)
322502156 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData}|Vault ID: 1C15CA8BF6E0C6844922F9523A03825D01110000evserver1|Status: 1|Limit Status: 0|Storage Svc: 17E3618165863464BA8E087E843340A4E1e10000evserver1|Rollover Vault :|Vault Store Status: 0
322502157 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData} (Exit) Status: [Success]
322502158 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus} (Entry)
322502159 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus:#1146} Storage Service [17E3618165863464BA8E087E843340A4E1e10000evserver1] throttle status: [DV_DS_AS_AVAILABLE (1)].
322502160 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus} (Exit) Status: [Success]
322502161 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx:#759} The throttle status for archive [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] is unchanged: [DV_DS_AS_AVAILABLE (1)].
322502162 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData} (Entry)
322502163 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData:#1225} Vault [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] status: [DV_DS_AS_AVAILABLE (1)]
322502164 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData} (Exit) Status: [Success]
322502165 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx:#793} Checked Storage information, and the throttle status for archive [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] is still [DV_DS_AS_AVAILABLE (1)].
322502166 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx} (Exit) Status: [Success]
322502167 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::ReserveQualifyingPosition:#199} bQualifyByAge[True] m_archivingstrategy[1]
322502168 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CPrioritizedItemTable::GetQualifyingPosition:#249} (Age) - Qualified to enter list
322502169 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::ReserveQualifyingPosition:#221} m_StandingQualifiedList[1] iCallerToken[28267]
322502170 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CPrioritizedItemTable::InsertRow:#283} (Age) - Inserting a new row
322502171 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::InsertItem:#166} insert age table item
322502172 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M :CArchivingAgent::IsEligibleForArchive() |Entering routine  |
322502173 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {MigratedDominoItems::IsMigratedDominoShortcut} (Entry)
322502174 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {PropsItem::HasShortcutProps:#149} Shortcut properties are not present (incorrect MAPI type; expecting PT_STRING8).
322502175 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {MigratedDominoItems::IsMigratedDominoShortcut:#198} Missing shortcut properties that are indicative of a migrated Domino shortcut.
322502176 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {MigratedDominoItems::IsMigratedDominoShortcut} (Exit) Status: [Success]
322502177 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {GetCalculatedModifiedDate:#1203} Calculated date (dd/mm/yyyy): [28/10/2014 22:34.43] [PR_MESSAGE_DELIVERY_TIME]
322502178 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L :CArchivingAgent::IsEligibleForArchive(/o=IMMI/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=PRAMUH35f) |The message titled: RE: Not well [SEC=UNCLASSIFIED] has the retention category of its parent folder its value  is 189E475016881914F924E2E5675D9D6891b10000evserver1   |
322502179 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L :CArchivingAgent::IsEligibleForArchive(/o=IMMI/ou=Exchange Administrative Group (FYDIBOHF23SPDLT)/cn=Recipients/cn=PRAMUH35f) |The message titled: RE: Not well [SEC=UNCLASSIFIED] is eligible for archive  |
322502180 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M :CArchivingAgent::IsEligibleForArchive() |Exiting routine |
322502181 10:26:08.370  [15436] (ArchiveTask) <27248> EV:M {CArchivingAgent::GetFolderPathForSavesetExchangeLocation:#5749} folder path to store [Inbox]
322502182 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CArchivingAgent::QueueEligibleItem:#24955} Eligible Item Strategy [Age]
322502183 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx} (Entry)
322502184 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData} (Entry)
322502185 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData}|Vault ID: 1C15CA8BF6E0C6844922F9523A03825D01110000evserver1|Status: 1|Limit Status: 0|Storage Svc: 17E3618165863464BA8E087E843340A4E1e10000evserver1|Rollover Vault :|Vault Store Status: 0
322502186 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusData} (Exit) Status: [Success]
322502187 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus} (Entry)
322502188 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus:#1146} Storage Service [17E3618165863464BA8E087E843340A4E1e10000evserver1] throttle status: [DV_DS_AS_AVAILABLE (1)].
322502189 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultThrottleStatus} (Exit) Status: [Success]
322502190 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx:#759} The throttle status for archive [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] is unchanged: [DV_DS_AS_AVAILABLE (1)].
322502191 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData} (Entry)
322502192 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData:#1225} Vault [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] status: [DV_DS_AS_AVAILABLE (1)]
322502193 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetStorageInfoData} (Exit) Status: [Success]
322502194 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx:#793} Checked Storage information, and the throttle status for archive [1C15CA8BF6E0C6844922F9523A03825D01110000evserver1] is still [DV_DS_AS_AVAILABLE (1)].
322502195 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CStorageArchive::GetVaultStatusEx} (Exit) Status: [Success]
322502196 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::ReserveQualifyingPosition:#199} bQualifyByAge[True] m_archivingstrategy[1]
322502197 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CPrioritizedItemTable::GetQualifyingPosition:#249} (Age) - Qualified to enter list
322502198 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::ReserveQualifyingPosition:#221} m_StandingQualifiedList[1] iCallerToken[19997]
322502199 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CPrioritizedItemTable::InsertRow:#283} (Age) - Inserting a new row
322502200 10:26:08.370  [15436] (ArchiveTask) <27248> EV:L {CEligibleItemList::InsertItem:#166} insert age table item

Cheers

Peter

[JimmyNeutron]

What type of storage is your VS partition on? Do you know if your AV maybe scanning those locations causing slow backups. This could mean that its not getting to all the items with that backup window.