-
One of my customers complaints of an unstable WCF service on his production environment. I heard them saying: "The service is frozen", "Getting unknown error from the client side UI", "The service is unresponsive". The real challenge of debugging a production issues is to reproduce it in some other kind of environment. And this is really a BIG task. But I was somewhat lucky; using my unit tests from a VSTS test client , I ran it for almost 10/12 hours until I reached a situation where all the complaints seem to be true. I took a memory dump of my WCF service process.
I tried to launch the client GUI. But unfortunately, after sometime I saw "Unknown Error" form the GUI. I checked the client side log and found something very interesting: 'The socket connection was aborted. This could be caused by an error processing your message or a receive timeout being exceeded by the remote host, or an underlying network resource issue. Local socket timeout was '00:09:59.7289458'.
I tried to visualize the launching of the GUI application. It will contact almost 5/6 endpoints of the back end WCF service before successfully launching it. So, I suspect it can be because of at least one of the endpoint which is timing out.
This great blog: http://blogs.msdn.com/mahjayar/archive/2006/12/12/debugging-wcf-applications.aspx really helped me to debug.
I started with dumping the ServiceHost types.
0:025> !dumpheap -type System.ServiceModel.ServiceHost
Statistics:
MT Count TotalSize Class Name
50e822f4 11 220 System.ServiceModel.ExtensionCollection`1[[System.ServiceModel.ServiceHostBase, System.ServiceModel]]
50eaf9c8 11 264 System.Collections.Generic.List`1[[System.ServiceModel.IExtension`1[[System.ServiceModel.ServiceHostBase, System.ServiceModel]], System.ServiceModel]]
50e62118 11 352 System.ServiceModel.ServiceHost+ReflectedContractCollection
50e553e8 11 1496 System.ServiceModel.ServiceHost
I found 11 instances of System.ServiceModel.ServiceHost type. I checked the wcf servicehost config file and found there are 11 endpoints configured. So, it makes sense.
My particular interest was to see if any of the endpoints had reached it's throttle limit. To look into it I dumped System.ServiceModel.Dispatcher.FlowThrottle type, and found 33 objects.
0:025> !dumpheap -type System.ServiceModel.Dispatcher.FlowThrottle
Address MT Size
00fe56f8 50e49ffc 36
00fe57b4 50e49ffc 36
0103bda8 50e49ffc 36
0110cc74 50e49ffc 36
0110cce4 50e49ffc 36
0112ef04 50e49ffc 36
01287bd0 50e49ffc 36
01287c40 50e49ffc 36
0129b290 50e49ffc 36
012d6a94 50e49ffc 36
012d6b04 50e49ffc 36
012e57b0 50e49ffc 36
01305bd8 50e49ffc 36
01305c48 50e49ffc 36
013114f4 50e49ffc 36
0132886c 50e49ffc 36
013288dc 50e49ffc 36
01332840 50e49ffc 36
01337950 50e49ffc 36
013379c0 50e49ffc 36
01357ba0 50e49ffc 36
013e873c 50e49ffc 36
013e87ac 50e49ffc 36
013f4744 50e49ffc 36
0150ebd8 50e49ffc 36
0150ec48 50e49ffc 36
01517d00 50e49ffc 36
01523768 50e49ffc 36
015237d8 50e49ffc 36
01530948 50e49ffc 36
015452b4 50e49ffc 36
01545324 50e49ffc 36
0154d508 50e49ffc 36
total 33 objects
Statistics:
MT Count TotalSize Class Name
50e49ffc 33 1188 System.ServiceModel.Dispatcher.FlowThrottle
Total 33 objects
I was little curious to know why 33 objects are present for 11 endpoints. I checked the endpoint behavior at the server side :
<behavior name="HermesServiceBehavior">
<serviceMetadata />
<serviceDebug includeExceptionDetailInFaults="true" />
<serviceThrottling maxConcurrentCalls="64"
maxConcurrentSessions="64"
maxConcurrentInstances="2147483647" />
</behavior>
So, it answers my question; each endpoint has the three throttle behaviors. => 11*3= 33 FlowThrottles
My next step was to dump all these FlowThrottle and check for any saturation.
0.25> .foreach (name {!dumpheap -type System.ServiceModel.Dispatcher.FlowThrottle -short}) {.echo -------------; .echo name; !do name}
My formatted output looked like this:
....................................................................
....................................................................
-------------
01287bd0
Name: System.ServiceModel.Dispatcher.FlowThrottle
MethodTable: 50e49ffc
EEClass: 50e49f8c
Size: 36(0x24) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System.ServiceModel\3.0.0.0__b77a5c561934e089\System.ServiceModel.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fdb60 400327b 18 System.Int32 1 instance 64 capacity
790fdb60 400327c 1c System.Int32 1 instance 0 count
790f8a7c 400327d 4 System.Object 0 instance 01287bf4 mutex
791118a4 400327e 8 ...ding.WaitCallback 0 instance 01287bb0 release
00000000 400327f c 0 instance 01287c00 waiters
790f9244 4003280 10 System.String 0 instance 00fe565c propertyName
790f9244 4003281 14 System.String 0 instance 00fe56a0 configName
-------------
01287c40
Name: System.ServiceModel.Dispatcher.FlowThrottle
MethodTable: 50e49ffc
EEClass: 50e49f8c
Size: 36(0x24) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System.ServiceModel\3.0.0.0__b77a5c561934e089\System.ServiceModel.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fdb60 400327b 18 System.Int32 1 instance 64 capacity
790fdb60 400327c 1c System.Int32 1 instance 64 count
790f8a7c 400327d 4 System.Object 0 instance 01287c64 mutex
791118a4 400327e 8 ...ding.WaitCallback 0 instance 01287c20 release
00000000 400327f c 0 instance 01287c70 waiters
790f9244 4003280 10 System.String 0 instance 00fe5620 propertyName
790f9244 4003281 14 System.String 0 instance 00fe5758 configName
-------------
0129b290
Name: System.ServiceModel.Dispatcher.FlowThrottle
MethodTable: 50e49ffc
EEClass: 50e49f8c
Size: 36(0x24) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System.ServiceModel\3.0.0.0__b77a5c561934e089\System.ServiceModel.dll)
Fields:
MT Field Offset Type VT Attr Value Name
790fdb60 400327b 18 System.Int32 1 instance 2147483647 capacity
790fdb60 400327c 1c System.Int32 1 instance 0 count
790f8a7c 400327d 4 System.Object 0 instance 0129b2b4 mutex
791118a4 400327e 8 ...ding.WaitCallback 0 instance 0129b270 release
00000000 400327f c 0 instance 0129b2c0 waiters
790f9244 4003280 10 System.String 0 instance 0103bd48 propertyName
790f9244 4003281 14
..................................................................................
It was a great output, because of this text in RED. This proves that I was guessing on the right direction. There is actually one endpoint which has reached the throttle limit.
But which endpoint is this, we have 11?
Let's dump the related ServiceHost type:
0:025> !do 01287a34
01287a34
Name: System.ServiceModel.ServiceHost
MethodTable: 50e553e8
EEClass: 50e55368
Size: 136(0x88) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System.ServiceModel\3.0.0.0__b77a5c561934e089\System.ServiceModel.dll)
Fields:
MT Field Offset Type VT Attr Value Name
79103c00 4000915 28 System.Boolean 1 instance 0 aborted
79103c00 4000916 29 System.Boolean 1 instance 0 closeCalled
.................................................................................................................
.................................................................................................................
50e04530 4002be2 3c ...erviceDescription 0 instance 01287cd0 description
00000000 4002be3 40 0 instance 01287b2c extensions
00000000 4002be4 44 0 instance 012d6834 externalBaseAddresses
00000000 4002be5 48 0 instance 01293a80 implementedContracts
50e124c0 4002be6 4c ...nceContextManager 0 instance 01287b58 instances
7910b5d8 4002be7 6c System.TimeSpan 1 instance 01287aa0 openTimeout
50df93e0 4002be8 50 ...rformanceCounters 0 instance 01295ef4 servicePerformanceCounters
50e1272c 4002be9 54 ...r.ServiceThrottle 0 instance 01287b80 serviceThrottle
50e321ac 4002bea 58 ...erviceCredentials 0 instance 00000000 readOnlyCredentials
50e1f218 4002beb 5c ...orizationBehavior 0 instance 012d67ec readOnlyAuthorization
00000000 4002bec 60 0 instance 00000000 UnknownMessageReceived
7a751b00 4002bdd 74c System.Uri 0 static 00fe546c EmptyUri
790f8a7c 4003075 74 System.Object 0 instance 00000000 singletonInstance
790ffe7c 4003076 78 System.Type 0 instance 01057f28 serviceType
50e62118 4003077 7c ...ontractCollection 0 instance 01287e00 reflectedContracts
7910b450 4003078 80 System.IDisposable 0 instance 00000000 disposableInstance
The name of the endpoint can be found in this ServiceDescription
0:025> !do 01287cd0
Name: System.ServiceModel.Description.ServiceDescription
MethodTable: 50e04530
EEClass: 50e04478
Size: 32(0x20) bytes
(C:\WINDOWS\assembly\GAC_MSIL\System.ServiceModel\3.0.0.0__b77a5c561934e089\System.ServiceModel.dll)
Fields:
MT Field Offset Type VT Attr Value Name
00000000 400306f 4 0 instance 01287cf0 behaviors
790f9244 4003070 8 System.String 0 instance 01287d9c configurationName
50dd0b68 4003071 c ...ndpointCollection 0 instance 01287d28 endpoints
790ffe7c 4003072 10 System.Type 0 instance 01057f28 serviceType
50dda3c4 4003073 14 ...scription.XmlName 0 instance 00000000 serviceName
790f9244 4003074 18 System.String 0 instance 00fe7a2c serviceNamespace
It should be inside configurationName.
0:025> !do 01287d9c
Name: System.String
MethodTable: 790f9244
EEClass: 790f91a4
Size: 100(0x64) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: **********.********.ExternalService
Fields:
MT Field Offset Type VT Attr Value Name
790fdb60 4000096 4 System.Int32 1 instance 42 m_arrayLength
790fdb60 4000097 8 System.Int32 1 instance 41 m_stringLength
790fad38 4000098 c System.Char 1 instance 4d m_firstChar
790f9244 4000099 10 System.String 0 shared static Empty
>> Domain:Value 001475b8:790d57b4 <<
79122994 400009a 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 001475b8:00fc13f4 <<
Here we go. The endpoint which is saturated with the max throttle limit is ExternalService. When the GUI launches it actually contacts this endpoint to get some data.
-
With the new wave of RIA, the applications are relying more on JavaScript for the rich user experience. The two key factors which influence the performance a.k.a end user experience are: JavaScript and the Client Processing Speed. With a standard client processor, it is not very uncommon to find plateau of high CPU utilization on the client side for inefficient JavaScript rendering logic.
To measure the time taken by JavaScript code at the client was a pain. Sometimes we used a tool, AjaxView, but it has it's own limitations (e.g. doesn't work with HTTPS, separately run a proxy and change the browser proxy etc.). In couple of my engagements where the site uses HTTPS , I preferred an age old method: counting the ticks from my wrist watch till the JavaScript rendering ends. But, with the arrival of IE8 developer tool, my life is too cool now form this perspective. I can profile, measure and support my findings with something solid on black and white. There is a good article from MSDN which talks about it.
For one of our customers we did the performance analysis of their website. Historically, whenever users click on a button on a particular page the CPU utilization at the client side reaches 100% and stays there for almost 2/3 minutes before users could do anything. On investigation we found two areas of improvement:
- JavaScript
- Network transfer
After sometime they claimed some of the issues had been fixed and the response time was improved. Though there were some improvements on the overall response time due to logic change in the network transfer, they did little to fix the JavaScript issue. To substantiate my claim I used Developers Tool of IE8 Beta2.
The following steps I followed:
- Open the website, go to the page where you suspect the event is present.
- Just before clicking on the problematic button(the scenario) launch Developer Tool (press F12),
- From the Profiler Tab Start Profiling.
![clip_image002[6]](http://blogs.msdn.com/blogfiles/banibrata_de/WindowsLiveWriter/IE8toolbarAstepforwardtomeasureRIAperfor_FC4F/clip_image002%5B6%5D_thumb.jpg)
4. Wait till the page load finishes then Stop Profiling.
Finally a very cool table as below was generated, which can be exported to an excel file. Here I looked for functions with higher Exclusive Time, (Inclusive Time contains other timings spent inside(in case a function calling other functions, etc.))
In my case I found this:
It indicates the JavaScript hotspots as the highlighted functions: UpdateEntitlementLicenseKey (executed 157 times) and OpenModal, overall it is consuming 17 seconds at the client machine. Moreover, during this transaction the CPU utilization reached 100% and stayed there for quite sometime.The time reported here is based on my PC's hardware configuration, it could vary depending on the hardware configuration of the client machine.
So, now I have a reason to go back to the developers and show them where the performance improvement is needed. Also developers can leverage the functionality of this cool profiler to identify the hotspots at the early stages of the development lifecycle to ensure end users' happiness.
-
In one of my engagements, I was doing the load test of a WCF application. I was using unit test for each of the scenario and mixed them together, to create the required workloads. In my case there were six scenarios. However, the interesting observation was that the load test results showed the system couldn't support more than 3 concurrent users, as the web server processor was 100% utilized. The task manager shows HERMES.SERVICEHOST.EXE as the process name causing this outage. I could have gone back to the app guys and told them "Hey look, this application sucks!', instead I took a different stand. With the help of much respected winDBG, I tried to analyze WHY the processor was so busy.
Let's investigate into "WHY"
My first step was to figure out which call/calls are heavy for the web server processor. Running each unit test individually, I found that out of 6 tests 3 tests are causing the problem, by showing the same pattern. I looked into the common set of service calls among these three tests, but I found many calls. However, I needed the exact call. So, I put break point on all the calls of a UNIT test and looked into the web server processor utilization with each F9 until I found the rogue call. It didn't take too long to find the evil. The Processor utilization reached around 80% and stayed there for almost 2 minutes.
From my UNIT test the call looked like
return dealClient.GenerateCps (localeId, .....................);
I confirmed the same call was responsible for other tests also. Now it was time to get into the processor's skin and my option was WinDBG.
I opened a command prompt from the web server debug directory, and typed this on (I didn't hit "ENTER" though)
adplus -hang -pn HERMES.SERVICEHOST.EXE -quiet
Then I went back to the my unit test with the break point set at "return dealClient.GenerateCps (localeId, .....................);" and ran the test in debug mode and when it reached this line, I pressed F9. I checked that the web server processor had almost hit the roof. I waited for couple of seconds before I hit the "ENTER" key from my earlier command prompt. Quietly it created the dump of the process in hang mode.
Who let the dogs out?
Let's spill the beans with winDBG. I used these set of commands in sequence .
0:000> .load sos.dll
.time : to know the uptimes of the system and the process (HERMES.SERVICEHOST.EXE)
0:000> .time
Debug session time: Tue Jul 29 16:25:29.000 2008 (GMT+6)
System Uptime: 9 days 3:37:40.437
Process Uptime: 0 days 5:04:45.000
Kernel time: 0 days 1:40:55.000
User time: 0 days 0:01:06.000
!runaway: to know which thread was consuming processor time in USER mode.
0:000> !runaway
User Mode Time
Thread Time
9:1ee8 0 days 0:23:17.765
3:318 0 days 0:00:01.218
2:1494 0 days 0:00:00.781
16:1b24 0 days 0:00:00.062
0:1214 0 days 0:00:00.046
21:1f1c 0 days 0:00:00.031
8:1060 0 days 0:00:00.031
14:1dec 0 days 0:00:00.015
5:1910 0 days 0:00:00.015
20:29c 0 days 0:00:00.000
19:1bc0 0 days 0:00:00.000
18:112c 0 days 0:00:00.000
17:1c84 0 days 0:00:00.000
15:1ca0 0 days 0:00:00.000
13:1c68 0 days 0:00:00.000
12:1d60 0 days 0:00:00.000
11:1c24 0 days 0:00:00.000
10:185c 0 days 0:00:00.000
7:1f30 0 days 0:00:00.000
6:1f90 0 days 0:00:00.000
4:1070 0 days 0:00:00.000
1:1330 0 days 0:00:00.000
The above output showed that the thread 9 in red had taken up the maximum time form the processor.
Now let's switch into this thread number 9 to see "WHY".
0:000> ~9s
eax=00000001 ebx=04d3ade0 ecx=0c851ec4 edx=0c851ee0 esi=0c851ec4 edi=00000004
eip=073d127f esp=040ec544 ebp=040ec568 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000202
073d127f 8bcf mov ecx,edi
!clrstack: to see what was on the execution stack of this long running thread
0:009> !clrstack
OS Thread Id: 0x1ee8 (9)
ESP EIP
040ec544 073d127f SoftArtisans.OfficeWriter.ExcelWriter.ᧀ.ᜄ(Int32)
040ec570 0eef988f SoftArtisans.OfficeWriter.ExcelWriter.᠑.ᜂ()
040ec594 0eef9669 SoftArtisans.OfficeWriter.ExcelWriter.ᩨ.ᜅ()
040ec5a0 0eef95a1 SoftArtisans.OfficeWriter.ExcelWriter.ᩨ.ᜀ(SoftArtisans.OfficeWriter.ExcelWriter.ᢦ)
040ec5cc 0eef954b SoftArtisans.OfficeWriter.ExcelWriter.ᩨ.ᜁ()
040ec5d0 0eef951c SoftArtisans.OfficeWriter.ExcelWriter..ᜀ(SoftArtisans.OfficeWriter.ExcelWriter.)
040ec5dc 0eef92e6 SoftArtisans.OfficeWriter.ExcelWriter..ᜀ()
040ec5e8 0eef913f SoftArtisans.OfficeWriter.ExcelWriter.៘.ᜀ()
040ec618 0eef90dd SoftArtisans.OfficeWriter.ExcelWriter.ᢥ.ᜁ(Int32)
040ec624 0eef8e86 SoftArtisans.OfficeWriter.ExcelWriter.ᤩ.ᜀ(SoftArtisans.OfficeWriter.ExcelWriter.ᣊ, Int32, SoftArtisans.OfficeWriter.ExcelWriter.)
040ec66c 0eef8d27 SoftArtisans.OfficeWriter.ExcelWriter.ᤩ.ᜀ()
040ec69c 0eef8cdb SoftArtisans.OfficeWriter.ExcelWriter.ឋ.ᜀ()
040ec6a0 0eef8c59 SoftArtisans.OfficeWriter.ExcelWriter.ᨀ.ᜀ()
040ec6d4 0740bcf1 MS.IT.Ops.Hermes.DataAccessObjects.GenerateCpsDAO.AssignProductInformation(System.Data.DataView, SoftArtisans.OfficeWriter.ExcelWriter.Worksheet, Int32 ByRef, System.Decimal ByRef, System.Data.DataTable, SoftArtisans.OfficeWriter.ExcelWriter.Palette, System.String, System.Globalization.CultureInfo)
040ec7cc 0aeb6c65 MS.IT.Ops.Hermes.DataAccessObjects.GenerateCpsDAO.GenerateCps(Int32, Int32, System.String, System.String, System.String, MS.IT.Ops.Hermes.DataTransferObjects.CPSData, System.String, MS.IT.Ops.Hermes.DataTransferObjects.ProposalEntity, MS.IT.Ops.Hermes.DataTransferObjects.CPSDomainData, System.String, Boolean, Boolean, System.DateTime, Boolean, MS.IT.Ops.Hermes.DataTransferObjects.Footer, Boolean)
040eed34 08407fc5 MS.IT.Ops.Hermes.BusinessComponents.Deal.GenerateCps(Int32, Int32, System.String, System.String, System.String, MS.IT.Ops.Hermes.DataTransferObjects.CPSData, System.String, MS.IT.Ops.Hermes.DataTransferObjects.ProposalEntity, MS.IT.Ops.Hermes.DataTransferObjects.CPSDomainData, System.String, Boolean, Boolean, System.DateTime, Boolean, MS.IT.Ops.Hermes.DataTransferObjects.Footer, Boolean)
040eed88 0464b34e MS.IT.Ops.Hermes.BusinessFacade.DealFacade.GenerateCps(System.String, System.String, MS.IT.Ops.Hermes.DataTransferObjects.ProposalEntity, Boolean, System.String, Int32, Int32, System.String, Boolean, System.DateTime, Boolean, MS.IT.Ops.Hermes.DataTransferObjects.Footer, Boolean)
040eee88 04649e6e MS.IT.Ops.Hermes.Services.DealService.MS.IT.Ops.Hermes.Services.IDeal.GenerateCps(Int32, System.String, System.String, MS.IT.Ops.Hermes.DataTransferObjects.ProposalEntity, Boolean, Boolean, System.String, Boolean, Boolean)
040eef7c 0822900c DynamicClass.SyncInvokeGenerateCps(System.Object, System.Object[], System.Object[])
040eefb8 50b09ede System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(System.Object, System.Object[], System.Object[] ByRef)
040ef030 50aeaff3 System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(System.ServiceModel.Dispatcher.MessageRpc ByRef)
040ef07c 508ad430 System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(System.ServiceModel.Dispatcher.MessageRpc ByRef)
040ef0bc 508ad286 System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage4(System.ServiceModel.Dispatcher.MessageRpc ByRef)
040ef0e8 508ad1f3 System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage3(System.ServiceModel.Dispatcher.MessageRpc ByRef)
040ef0f8 508ad039 System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage2(System.ServiceModel.Dispatcher.MessageRpc ByRef)
040ef108 508ac281 System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage1(System.ServiceModel.Dispatcher.MessageRpc ByRef)
040ef12c 508abfaf System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean)
040ef170 508ab8a4 System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(System.ServiceModel.Channels.RequestContext, Boolean, System.ServiceModel.OperationContext)
040ef31c 508a9e22 System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(System.ServiceModel.Channels.RequestContext, System.ServiceModel.OperationContext)
040ef360 508a98ee System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(System.IAsyncResult)
040ef374 508a9881 System.ServiceModel.Dispatcher.ChannelHandler.OnAsyncReceiveComplete(System.IAsyncResult)
040ef380 50212c98 System.ServiceModel.Diagnostics.Utility+AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult)
040ef3ac 5089f211 System.ServiceModel.AsyncResult.Complete(Boolean)
040ef3e8 508a963c System.ServiceModel.Channels.FramingDuplexSessionChannel+TryReceiveAsyncResult.OnReceive(System.IAsyncResult)
040ef418 50212c98 System.ServiceModel.Diagnostics.Utility+AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult)
040ef444 5089f211 System.ServiceModel.AsyncResult.Complete(Boolean)
040ef480 508a93e1 System.ServiceModel.Channels.SynchronizedMessageSource+ReceiveAsyncResult.OnReceiveComplete(System.Object)
040ef4ac 508a55fd System.ServiceModel.Channels.SessionConnectionReader.OnAsyncReadComplete(System.Object)
040ef4ec 508cffa2 System.ServiceModel.Channels.StreamConnection.OnRead(System.IAsyncResult)
040ef4f8 50212c98 System.ServiceModel.Diagnostics.Utility+AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult)
040ef524 5089f211 System.ServiceModel.AsyncResult.Complete(Boolean)
040ef560 508cf689 System.ServiceModel.Channels.ConnectionStream+ReadAsyncResult.OnAsyncReadComplete(System.Object)
040ef58c 50901c29 System.ServiceModel.Channels.SocketConnection.FinishRead()
040ef594 50901afb System.ServiceModel.Channels.SocketConnection.AsyncReadCallback(Boolean, Int32, Int32)
040ef5d8 5089efe8 System.ServiceModel.Channels.OverlappedContext.CompleteCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
040ef5f0 50212d9f System.ServiceModel.Diagnostics.Utility+IOCompletionThunk.UnhandledExceptionFrame(UInt32, UInt32, System.Threading.NativeOverlapped*)
040ef624 793d6140 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
040ef7c8 79e7be1b [GCFrame: 040ef7c8]
And BINGO! it is actually generating a file with ExcelWriter, which is very expensive in terms of processor utilization. Later, I talked with the application team and they confirmed it.
-
Out of curiosity I was toying with Http Professional 5.2 and some high performance web sites which use Ajax. Incidentally, I tried Google's http://www.google.com/webhp?complete=1&hl=en. and found something interesting.
This feature is cool as it guides the users to search for particular strings (Fig. 1), by pre-fetching possible matches from the back end.
I started, HttpWatch Professional 5.2, from my IE 7.0 and captured the following screen shots. My intention was to search for a term which will show some valid results once I hit the search button. So, I thought of starting with my first name "banibrata".
Google suggest is a very good user experience. I started with "b", it gave me many suggestions (Fig 1), and my HttpWatch registered a network call to the back end (Fig 2). The call looked like: http://www.google.com/complete/search?hl=en&client=suggest&js=true&q=b&cp=1. As I went on typing "a", "n", "i", it made similar calls and I got the suggestions almost instantly. But once I typed "banib", it seemed, I had reached the end of Google suggest's wit. I kept on typing until I complete my first name : "banibrata".
Observation
HttpWatch showed, even though Google stopped suggesting me, it made the same asynchronous call to the back end for each letter I typed "banib" onwards, which no result, for these requests (Fig 3 and Fig 4).
Though from an end user's stand point this doesn't affect the performance, from the over all system perspective, it is making a network round trip for each letter, which doesn't make sense here.
Fig. 1
Fig. 2
Fig. 3
Fig. 4
Are these calls required? This is just adding to network round trips, though from the end-users perspective it doesn't matter, it has a performance overhead, whatever little it may seem. The logic can be modified in such a way that once the suggestion from the back end stops, typing forward will not result a call to the back end.
