Slow item recall with EV 11 OWA users.

Question

Hi

I've just recently upgraded a customer from EV10.0.1 to EV11 and now the OWA access seems to be very slow when opening an item. It takes about 12 - 15secs. Which is a long time when you're sitting wathcing it - it will always eventually open, but I'm trying to find out why it takes so long.

When EV10 was upgraded the EV server was also moved to a new Windows 2012 platform and had a new IP address and server name. DNS aliases were all updated and everything else works fine with the exception of the OWA.&nbsp;

I'm not entirely sure how long it took prior to the server upgrade\migration but the customer says it was significantly shorter in time (perhaps &lt;5s)

I've got some logs and dtraceand followed a couple of recommended tests - but wanted to post some log information to see if anyone can confirm where I'm seeing delays as the root cause and also suggestions on why these dalys may be experienced.

I did check the time it takes to restore an item in Archive Explorer and IMO this also seemed slower than I would have expected - not as slow as opening an item in OWA but a tad longer than I would have thought.

The OWA issues is evident with both internal and external OWA access, affects all the users and is no different with differing versions of IE.

I've the a full web.config log available if useful but just initially wanted to see if the following delay I saw is key to the issue

I've highligted a 7s delay in recieving a response from the EV Server...... Is this normal??

25/07/2014 15:17:38 [8572,1] [EVServerRequest::AddHeader] Set header: EV-OWA-2010-Extensions-Version=11.0.0.0
	25/07/2014 15:17:38 [8572,1] [EVServerRequest::CreateRequest] Making request for user: My.Domain\A.user
	25/07/2014 15:17:38 [8572,1] [EVServerRequest::AddHeader] Set header: X-EVOWA-User-Encoded=5500500050002D004C00540044005C00640061006E00690065006C002E006200750063006B0069006E006700680061006D00
	25/07/2014 15:17:45 [8572,1] [EVServerRequest::LogResponseHeaders] Response received from EV server:
	25/07/2014 15:17:45 [8572,1] [EVServerRequest::LogResponseHeaders] &nbsp; Status: 201 Basket Restoring
	25/07/2014 15:17:45 [8572,1] [EVServerRequest::LogResponseHeaders] &nbsp; Headers:&nbsp;
	25/07/2014 15:17:45 [8572,1] [EVServerRequest::LogResponseHeaders] &nbsp; &nbsp; Content-Length: 16

Below is a section of Dtrace - with a delay around the basket deletion - so again is this normal?

There is a delay of 6s in the sequence below, but this seems to occur AFTER the basket has been successfully restored so may be a red herring......

252&nbsp;&nbsp; &nbsp;15:02:02.709&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;380&gt;&nbsp;&nbsp; &nbsp;EV:M&nbsp;&nbsp; &nbsp;The following basket description has been successfully saved to disk:| Shopper: My.Domain\OWAUser| BasketID: 20140725150202256 |
	253&nbsp;&nbsp; &nbsp;15:02:02.709&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;380&gt;&nbsp;&nbsp; &nbsp;EV:H&nbsp;&nbsp; &nbsp;Successfully restored the following basket.| Shopper: My.Domain\OWAUser| BasketID: 20140725150202256| |
	254&nbsp;&nbsp; &nbsp;15:02:02.709&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;380&gt;&nbsp;&nbsp; &nbsp;EV:L&nbsp;&nbsp; &nbsp;The following basket has been successfully built:| Shopper: My.Domain\OWAUser| BasketID: 20140725150202256 |
	255&nbsp;&nbsp; &nbsp;15:02:02.709&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;380&gt;&nbsp;&nbsp; &nbsp;EV:L&nbsp;&nbsp; &nbsp;The following basket has been successfully built:| Shopper: My.Domain\OWAUser| BasketID: 20140725150202256 |
	256&nbsp;&nbsp; &nbsp;15:02:02.709&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;380&gt;&nbsp;&nbsp; &nbsp;EV:H&nbsp;&nbsp; &nbsp;Deleted the following basket:| |Shopper: My.Domain\OWAUser| |BasketID: 20140725150202256 |
	269&nbsp;&nbsp; &nbsp;15:02:08.822&nbsp;&nbsp; &nbsp; [2524]&nbsp;&nbsp; &nbsp;(ShoppingService)&nbsp;&nbsp; &nbsp;&lt;6624&gt;&nbsp;&nbsp; &nbsp;EV:H&nbsp;&nbsp; &nbsp;Failed to find the following basket description:| Shopper: My.Domain\vaultservice| BasketID: 20140725150202256 |
	270&nbsp;&nbsp; &nbsp;15:02:08.822&nbsp;&nbsp; &nbsp; [2524]&nbsp;&nbsp; &nbsp;(ShoppingService)&nbsp;&nbsp; &nbsp;&lt;6624&gt;&nbsp;&nbsp; &nbsp;EV:L&nbsp;&nbsp; &nbsp;Failed to update the restoration status of a restoring item because the basket has been deleted. |
	277&nbsp;&nbsp; &nbsp;15:02:12.378&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;7488&gt;&nbsp;&nbsp; &nbsp;EV:L&nbsp;&nbsp; &nbsp;CIndexSearch2::Reset
	278&nbsp;&nbsp; &nbsp;15:02:12.378&nbsp;&nbsp; &nbsp; [2060]&nbsp;&nbsp; &nbsp;(w3wp)&nbsp;&nbsp; &nbsp;&lt;7488&gt;&nbsp;&nbsp; &nbsp;EV:L&nbsp;&nbsp; &nbsp;CIndexSearch2::FinalRelease

&nbsp;

Any thoughts greatfully recieved - can post the entire log if necessary.

kind regards

KL

&nbsp;

andrewb · Answer

i just saw another thread on the forum where a slowness issue was resolved by turning off certificate revocation. not sure if it's what you're seeing but might be worth a shot.

http://www.symantec.com/docs/HOWTO57491

keirl · Answer

Thanks Andrew

Sorry for the late reply - I was just checking into your suggestion &nbsp;- but I don't think that's it. The EV server does have internet access and the other symptoms such as the slow VAC opening etc aren't there.

I've gone through the logs again and have a question on the process of getting the item from the shopping basket to the 'deleted items' folder in the users mailbox. As the Exchange server and the EV server are both VM’s they share the same time which is useful in understanding the sequence of events.

I’m currently trying to undersand if the following log extracts from a recent test are significant

Below is an extract from the web.config log of when the request was received to open an archived item at 15:13:03.

25/07/2014 15:13:03 [8572,5] #############################################################

25/07/2014 15:13:03 [8572,5] Request processing started

25/07/2014 15:13:03 [8572,5] Url:

25/07/2014 15:13:03 [8572,5] Query String parameters:

25/07/2014 15:13:03 [8572,5]&nbsp;&nbsp;&nbsp;&nbsp; ae: Item

25/07/2014 15:13:03 [8572,5]&nbsp;&nbsp;&nbsp;&nbsp; a: Open

25/07/2014 15:13:03 [8572,5]&nbsp;&nbsp;&nbsp;&nbsp; t: IPM.Note.EnterpriseVault.Shortcut

25/07/2014 15:13:03 [8572,5]&nbsp;&nbsp;&nbsp;&nbsp; id: RgAAAACG2EGO+nhZRq9ycjuGzt6CBwDcr7+GHwklS6mVo74WlPiMAAABAbpwAAALPa3YhCdXSrQpA09b/sGKAAAH8mpIAAAJ

&nbsp;

25/07/2014 15:13:03 [8572,5] [EVServerRequest::AddHeader] Set header: X-EVOWA-User-Encoded=5500500050002D004C00540044005C00640061006E00690065006C002E006200750063006B0069006E006700680061006D00

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders] Response received from EV server:

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp; Status: 201 Basket Restoring

The last two lines indicate that a response was received back from the EV server at 15:13:08 (5 secs later)

Below is now the Dtrace of the same request from the EV server.

Enabled Trace options

&nbsp;

Id&nbsp;&nbsp;&nbsp; Name&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; Detail&nbsp;&nbsp;&nbsp;&nbsp; Include Events

6&nbsp;&nbsp; - AuthServer&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &nbsp;Verbose&nbsp;&nbsp;&nbsp; Yes&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;

96&nbsp; - ShoppingService&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; Verbose&nbsp;&nbsp;&nbsp; Yes

108 - w3wp&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &nbsp;Verbose&nbsp;&nbsp;&nbsp; Yes&nbsp;&nbsp;&nbsp;&nbsp;

&nbsp;

1233&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 15:13:08.679&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [2228]&nbsp;&nbsp; (AuthServer)&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &lt;8132&gt;&nbsp; EV:L&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; {CClientAuthIntImpl::CancelClientIdentity:#965} Token [CUSTSRVEV3.MYDOMAIN.local =ea5124=8mXy*****], Cancel Id [33239312].

1234&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 15:13:08.679&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [2060]&nbsp;&nbsp; (w3wp)&nbsp;&nbsp; &lt;5092&gt;&nbsp; EV:M&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; The following basket description has been successfully saved to disk:| Shopper: MYDOMAIN\OWAUser| BasketID: 20140725151304359 |

1235&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; 15:13:08.679&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; [2060]&nbsp;&nbsp; (w3wp)&nbsp;&nbsp; &lt;5092&gt;&nbsp; EV:H&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; Successfully restored the following basket.| Shopper: MYDOMAIN\OWAUser| BasketID: 20140725151304359| |

The last line here shows the basket as being Successfully restored??

This is about the same time as the Web.config log showed the “Response received from EV server”

However back to the Web.config log – I can see the first check for the item in the deleted items shows the item count is 0 (end of the below extract)

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders] Response received from EV server:

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp; Status: 201 Basket Restoring

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp; Headers:

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp;&nbsp;&nbsp; Content-Length: 16

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp;&nbsp;&nbsp; Cache-Control: private

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp;&nbsp;&nbsp; Content-Type: text/html

25/07/2014 15:13:08 [8572,5] [EVServerRequest::LogResponseHeaders]&nbsp;&nbsp;&nbsp;&nbsp; Date: Fri, 25 Jul 2014 14:13:08 GMT

25/07/2014 15:13:10 [8572,5] [EWSBase::GetRestoredItemId] Item count: 0

&nbsp;

This is 2 seconds after the EV server had logged the basket as being restored?

The Web.config then proceeds to check for another 4 times (at 2 second intervals before it shows the item count = 1

&nbsp;

25/07/2014 15:13:18 [8572,5] EwsResponse:

&lt;Trace Tag="EwsResponse" Tid="5" Time="2014-07-25 14:13:18Z" Version="14.01.0218.002"&gt;

&nbsp; &lt;?xml version="1.0" encoding="utf-8"?&gt;

25/07/2014 15:13:18 [8572,5] [EWSBase::GetRestoredItemId] Item count: 1

25/07/2014 15:13:18 [8572,5] [RequestProcessor::RestoreAndActOnItem] Item has been restored

25/07/2014 15:13:18 [8572,5] [Id::OwaId] Converting EwsId to OwaId

&nbsp;

So not until 15:13:18 seconds does the user get to see the item&nbsp; - a wait time of 15 seconds from the initial request.

But my questions are

&nbsp;– the ev server seems to the basket restored in the first 5 secs yet it doesn’t appear to be in the deleted items for a further 10 secs after this. Does this indiciate a delay somewhere in the Exchange processing?

Are there any other logs that might help to narrow this down further.

To be honest I’m not actually looking for a fix, just opinions as to if these logs indicate an issue or ‘just how it is’….. I can log a support call with Symantec to get their view but thought I’d try a few guru’s first.

&nbsp;

Kind regards

KL

Forum Discussion

Slow item recall with EV 11 OWA users.

2 Replies

Related Content

FSA recall error

Enterprisevault no longer accesible for users

sysadmin user

How to find which user initiated immediate/user-directed backup?

Adding new user to Netbackup