Print Page | Close Window

Resolve Probing Performance!

Printed From: IdeaBlade
Category: DevForce
Forum Name: DevForce 2010
Forum Discription: For .NET 4.0
URL: http://www.ideablade.com/forum/forum_posts.asp?TID=2992
Printed Date: 13-May-2026 at 6:18pm


Topic: Resolve Probing Performance!
Posted By: Vonzkie
Subject: Resolve Probing Performance!
Date Posted: 06-Oct-2011 at 8:04pm
Hi,

I understand that the Startup Probing may have delay depending on the size of the model and there are techniques to control the SearchPattern on Startup Probing. -> We're good with this part

However, I noticed that even the DataSourceKey has probing based on the TraceViewer w/c is done when the first instance of the query is executed and this is slower than the Startup Probing not to mention the first instance of the Save process.

Startup Probing - 4 seconds -> Good
DataSourceKey Probing - 10 seconds -> Very Bad 
Save Probing - 8 seconds -> Very Bad

The question here is that is there a way to improve this process because this is very unacceptable in our part!

I thought that the DataSourceKey probing and Saving is only done once when the first instance of the these process was requested and will only be reset if the IIS Server is shutdown or other related Server maintenance procedures.

My first proposed workaround is to execute a mock query and save just to spin up these probing process at the server, we can't do with the Startup Probing because this is done on the client side.
But after more or less an hour, it seems that there's an expiration of this probing process because when I try to initiate a query and save once again, there's a probing.....................................................

If there are no way to improve these probing process, is there a way to create a one-time probing process without an expiration unless the server is shutdown?

Btw, we're talking about less than 200 entities here, and it's already trimmed down per module because we have 500 tables all in all.

Your help will be highly appreciated.

Thanks,
Von


Replies:
Posted By: kimj
Date Posted: 07-Oct-2011 at 8:42am
Hi Von,
 
Can you upload a debug log which shows these timing issues?  I want to separate "probing" from other initialization activities to see what's taking up the time. 
 
In general, though, you can address startup probing with changes to the CompositionHost IgnorePatterns and/or SearchPatterns.  Even though you've already done this, 4 seconds still sounds like a long time.
 
As for data source key "probing", there are several things going on here which I hope your debug log will explain further.  There is probing of the model to look for various attributes needed by DevForce; the Entity Framework will also "probe" for the EDMX metadata files; and a first query or save will also incur some EF overhead for view generation.  At various points DevForce will also obtain and load metadata about the model. 
 
Once we see your log we should know more about where the specific problem areas are.

Posted By: Vonzkie
Date Posted: 10-Oct-2011 at 1:29am
Hi Kimj,

Thanks for the response.

Now I understand the difference between probing and other Devforce activities and it appears that my startup probing "alone" is only 1 second.

Here's my debuglog from Server, as you can see below when I initiate a query using my ContextManagerBase class, it has some amount of delay as well as the saving process. 

Can you help me optimized this?

Note that I don't have any customized CompositionContext used here.

<?xml version="1.0"?><?xml-stylesheet href="DebugLog.xsl" type="text/xsl"?><log>
<entry id="10" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.TraceFileXmlLogger:GetLogHeader">------------ Log Created ------------</entry>
<entry id="0" timestamp="2011-10-10T16:32:42" username="" source="IdeaBlade.Core.IdeaBladeConfig:Initialize">Initializing configuration ...</entry>
<entry id="1" timestamp="2011-10-10T16:32:42" username="" source="IdeaBlade.Core.Composition.PartsCatalog:LoadCatalog">MEF assembly probing started: 10/10/2011 4:32:42 PM.  If this takes a long time, use IdeaBlade.Core.Composition.CompositionHost to specify/restrict which assemblies to probe.</entry>
<entry id="2" timestamp="2011-10-10T16:32:42" username="" source="IdeaBlade.Core.Composition.PartsCatalog:LoadCatalog">Assembly 'iRely.ConnectionManager, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' added to PartsCatalog</entry>
<entry id="3" timestamp="2011-10-10T16:32:43" username="" source="IdeaBlade.Core.Composition.PartsCatalog:LoadCatalog">MEF assembly probing completed: 10/10/2011 4:32:43 PM</entry>
<entry id="4" timestamp="2011-10-10T16:32:43" username="" source="IdeaBlade.Core.Composition.CompositionHost:.ctor">Probe Assemblies: iRely.ConnectionManager, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null :: iRely.VisionCore.Model, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null  If this list is unnecessarily large, use CompositionHost.SearchPatterns to modify the search critieria for probed assemblies. If this list does not contain the assembly(ies) holding your a) domain model, b) custom interface implementations, and c) POCO/known types then your application may not work correctly. Ensure that these assemblies are available in the exe/bin folder, and if using CompositionHost.SearchPatterns that the patterns are set appropriately.</entry>
<entry id="5" timestamp="2011-10-10T16:32:43" username="" source="IdeaBlade.Core.IdeaBladeConfig:InitializationStatusCallback">IdeaBlade License: 'EnterpriseUniv', KeyDate: 9/19/2011, AllowedSessions: 10000. Found on Assembly: 'iRely.VisionCore.Model, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null'</entry>
<entry id="6" timestamp="2011-10-10T16:32:43" username="" source="IdeaBlade.Core.Configuration.ServerSettingsElement:ConstrainSettingsBasedOnLicenseCore">The configured SupportedClientApplicationType is Both</entry>
<entry id="7" timestamp="2011-10-10T16:32:43" username="" source="IdeaBlade.Core.Configuration.ServerSettingsElement:ConstrainSettingsBasedOnLicenseCore">Could not find a valid license to enable session-agnostic load balancing.</entry>
<entry id="8" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for non-default 'ITraceLoggerProvider' and found no matching exports.</entry>
<entry id="9" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for default 'ITraceLoggerProvider' and found 'IdeaBlade.Core.DefaultLoggerProvider'.</entry>
<entry id="11" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.TraceFns:CompleteTracingInitialization">IdeaBladeConfig resolution: File: D:\70_VisionCore\iRely Applications\iRely.VisionCore.BusinessObjectServer\web.config - found</entry>
<entry id="12" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.TraceFns:CompleteTracingInitialization">IdeaBladeConfig resolution: Logging file: D:\70_VisionCore\iRely Applications\iRely.VisionCore.BusinessObjectServer\log\DebugLog.xml</entry>
<entry id="13" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.TraceFns:CompleteTracingInitialization">Bound to .NET runtime version 4.0.30319.225</entry>
<entry id="14" timestamp="2011-10-10T16:32:44" username="" source="IdeaBlade.Core.TraceFns:CompleteTracingInitialization">DevForce version 6.1.2.0</entry>
<entry id="15" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.EntityModel.Server.EntityServiceHost:AddBehaviors">Using DC serializer for EntityService</entry>
<entry id="16" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for any 'ServiceHostEvents' and found 'IdeaBlade.EntityModel.Server.ServiceHostEvents'.</entry>
<entry id="17" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.EntityModel.Server.EntityServiceHostFactory:CreateServiceHost">EntityService listening on http://ivon.comtech.com/iRely.VisionCore.BusinessObjectServer/EntityService_VisionCoreOriginalHere.svc</entry>
<entry id="18" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for any 'EntityServiceApplication' and found 'IdeaBlade.EntityModel.EntityServiceApplication'.</entry>
<entry id="19" timestamp="2011-10-10T16:32:50" username="" source=":CreateIdeaBlade.EntityModel.Server.RemoteEntityService">EntityService created</entry>
<entry id="20" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.EntityModel.Server.EntityServer:.ctor">EntityServer created for DataSourceExtension: VisionCoreOriginalHere, CompositionContext: -IbDefault-</entry>
<entry id="21" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for any 'IEntityQueryExecutor' and found 'IdeaBlade.EntityModel.Edm.EdmQueryExecutor'.</entry>
<entry id="22" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for any 'IEntityQueryExecutor' and found 'IdeaBlade.EntityModel.Edm.PassthruEsqlQueryExecutor'.</entry>
<entry id="23" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for any 'IEntityQueryExecutor' and found 'IdeaBlade.EntityModel.Edm.StoredProcQueryExecutor'.</entry>
<entry id="24" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for any 'IEntityQueryExecutor' and found 'IdeaBlade.EntityModel.Edm.UdtQueryExecutor'.</entry>
<entry id="25" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.EntityModel.Server.SessionManager:GetLoginManager">Anonymous access: disabled</entry>
<entry id="26" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for non-default 'IEntityLoginManager' and found 'iRely.ConnectionManager.ConnectionSecurityIEntityLoginManager'.</entry>
<entry id="27" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for non-default 'IKnownTypeProvider' and found no matching exports.</entry>
<entry id="28" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.EntityModel.Server.EntityServerHost:&lt;AddBehaviors&gt;b__2">Using DC serializer for EntityServer</entry>
<entry id="29" timestamp="2011-10-10T16:32:50" username="" source="IdeaBlade.EntityModel.Server.EntityServerHostFactory:CreateServiceHost">EntityServer_VisionCoreOriginalHere listening on http://ivon.comtech.com/iRely.VisionCore.BusinessObjectServer/EntityServer_VisionCoreOriginalHere.svc</entry>
<entry id="30" timestamp="2011-10-10T16:32:53" username="ContextManagerBase" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for any 'EntityServerQueryInterceptor' and found 'iRely.ConnectionManager.EntityServerQueryManager'.</entry>
<entry id="31" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblSMSearch])</entry>
<entry id="32" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for default 'IDataSourceKeyResolver' and found 'IdeaBlade.EntityModel.DefaultDataSourceKeyResolver'.</entry>
<entry id="33" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for non-default 'IDataSourceKeyResolver' and found 'iRely.ConnectionManager.CustomDataSourceKeyResolver'.</entry>
<entry id="34" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for any 'IIdGenerator' and found 'IdeaBlade.EntityModel.StoreGeneratedIdGenerator'.</entry>
<entry id="35" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for non-default 'IConcurrencyStrategy' and found no matching exports.</entry>
<entry id="36" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for default 'IConcurrencyStrategy' and found 'IdeaBlade.EntityModel.DefaultConcurrencyValueSetter'.</entry>
<entry id="37" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.EntityModel.Edm.EdmKey:FindClientAssembly">DataSourceKey probing started at 10/10/2011 4:32:54 PM</entry>
<entry id="38" timestamp="2011-10-10T16:32:54" username="ContextManagerBase" source="IdeaBlade.EntityModel.Edm.EdmKey:FindClientAssembly">DataSourceKey: 'VisionCoreEntities_VisionCoreOriginalHere' found in assembly 'iRely.VisionCore.Model, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' at 10/10/2011 4:32:54 PM</entry>
<entry id="39" timestamp="2011-10-10T16:33:02" username="" source="IdeaBlade.EntityModel.EntityServerProxy:CreateInstance">Loaded IdeaBlade.EntityModel.EntityServerProxy</entry>
<entry id="40" timestamp="2011-10-10T16:33:02" username="ContextManagerBase" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblSMSearch]).Where(p =&gt; ((p.strTableName == "tblARCustomer") AndAlso (p.intSecurityUserID == 1)))</entry>
<entry id="41" timestamp="2011-10-10T16:33:02" username="" source="IdeaBlade.Core.DynamicTypeInfo:get_DynamicType">DynamicType constructed _IB_ivGLpM86vXHw6uJ6</entry>
<entry id="42" timestamp="2011-10-10T16:33:02" username="ContextManagerBase" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARCustomer]).Select(t =&gt; new _IB_ivGLpM86vXHw6uJ6() {intCustomerID = t.intCustomerID, strAddress = t.strAddress, strCity = t.strCity, strCompanyName = t.strCompanyName, strCustomerID = t.strCustomerID, strCustomerType = t.strCustomerType, strEmail = t.strEmail, strFirstName = t.strFirstName, strLastName = t.strLastName, strPhone = t.strPhone, strSalesperson = t.strSalesperson, strState = t.strState, strZip = t.strZip, ysnAcceptBO = t.ysnAcceptBO, ysnActive = t.ysnActive}).Count()</entry>
<entry id="43" timestamp="2011-10-10T16:33:03" username="ContextManagerBase" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARCustomer]).Select(t =&gt; new _IB_ivGLpM86vXHw6uJ6() {intCustomerID = t.intCustomerID, strAddress = t.strAddress, strCity = t.strCity, strCompanyName = t.strCompanyName, strCustomerID = t.strCustomerID, strCustomerType = t.strCustomerType, strEmail = t.strEmail, strFirstName = t.strFirstName, strLastName = t.strLastName, strPhone = t.strPhone, strSalesperson = t.strSalesperson, strState = t.strState, strZip = t.strZip, ysnAcceptBO = t.ysnAcceptBO, ysnActive = t.ysnActive}).OrderBy(Param_0 =&gt; Param_0.intCustomerID)</entry>
<entry id="44" timestamp="2011-10-10T16:33:07" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARCustomer]).Where(p =&gt; True).OrderByDescending(t =&gt; t.intCustomerID).Count()</entry>
<entry id="45" timestamp="2011-10-10T16:33:07" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARCustomer]).Where(p =&gt; True).OrderByDescending(t =&gt; t.intCustomerID).Take(25)</entry>
<entry id="46" timestamp="2011-10-10T16:33:08" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARCustomer]).Where(t =&gt; (t.intCustomerID == 38)).OfType().SelectMany(t =&gt; t.tblARCustomerContacts)</entry>
<entry id="47" timestamp="2011-10-10T16:33:08" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblSMShipVia]).Where(t =&gt; (t.intShipViaID == 4))</entry>
<entry id="48" timestamp="2011-10-10T16:33:08" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARTaxCode]).Where(t =&gt; (t.intTaxCodeID == 88))</entry>
<entry id="49" timestamp="2011-10-10T16:33:09" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblSMTerm]).Where(t =&gt; (t.intTermID == 3))</entry>
<entry id="50" timestamp="2011-10-10T16:33:09" username="ContextManager" source="IdeaBlade.EntityModel.Server.EntityServerQueryInterceptor:ExecuteQuery">Fetch ... value(IdeaBlade.EntityModel.EntityQueryProxy`1[iRely.VisionCore.Model.tblARTaxCode]).Where(t =&gt; (t.intTaxCodeID == 88))</entry>

between here I initiated a save process.. More or less 2011-10-10T16:33:10 or 11

<entry id="51" timestamp="2011-10-10T16:33:15" username="" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for any 'ICompositionContextResolver' and found no matching exports.</entry>
<entry id="52" timestamp="2011-10-10T16:33:16" username="ContextManager" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for any 'EntityServerSaveInterceptor' and found 'iRely.ConnectionManager.EntityServerSaveManager'.</entry>
<entry id="53" timestamp="2011-10-10T16:33:16" username="ContextManager" source="IdeaBlade.Core.Composition.CompositionHost:CheckMultiExport">CompositionContext: '-IbDefault-' - Probed for non-default 'IVerifierProvider' and found no matching exports.</entry>
<entry id="54" timestamp="2011-10-10T16:33:16" username="ContextManager" source="IdeaBlade.Core.Composition.CompositionHost:GetImportDefSingle">CompositionContext: '-IbDefault-' - Probed for any 'IEdmSaveExecutor' and found 'IdeaBlade.EntityModel.Edm.EdmSaveExecutor'.</entry>
</log>

Thanks,
Von

Posted By: kimj
Date Posted: 10-Oct-2011 at 12:41pm

To briefly summarize what I see here -

 
- Total initialization time, from start at 16:32:42 until service startup at 16:32:50, seems long.  The MEF "discovery" portion is taking only 1 second, and other DevForce initialization from 16:32:43 to 16:32:44 is taking only a second, but there's a 6 second gap from 16:32:44 to 16:32:50 that is surprising.  This is where the EntityService WCF service is actually started and 6 seconds seems excessive.  The delay could be due to IIS service compilation, other services in your application also starting, memory issues - it's difficult to know without further analysis.

- The first query starts at 16:32:53.  The first query will trigger probing for various interface implementations, and also data source key "probing".  All of this probing is completed by 16:32:54, so I'm not seeing a problem here.

- I'm curious as to what's going on in your application at 16:32:02, though.  The log message indicates that a "client-side" communication proxy has been created, which you don't normally want to do on the BOS.  This can happen when creating a new EntityManager and not using one supplied by DevForce in the various interceptors, etc.

- The first save is starting at 16:33:15.  I know you say you've initiated it earlier, but the first sign that DevForce is processing the save on the server is that message at 16:33:15.  Maybe you're seeing a gap from when the client application makes the save and it's received by the BOS?  If that's the case, then we'd need to look at how much data is being saved.

--

So the major performance problem I see here is the initial startup.  Can you send us your web.config, and also information on your IIS and OS versions and system configuration so we can look into this further?  You can send this directly to IdeaBladeSupportTrack and reference task #11101.

Since you've implemented custom query and save interceptors it might help to add diagnostic tracing to see how long each of the query/save actions is taking.  That will help identify hotspots. 

As I mentioned above, creating a "client-side" communication proxy is generally not wanted when running on the server, so information on what you need here, and where it's happening (eg, in your custom login manager or interceptors, an RPC method?) will help us recommend a better approach.

Posted By: Vonzkie
Date Posted: 10-Oct-2011 at 7:05pm
Hi Kimj,

I wasn't able to post to the Technical Support Page, the Request Help button is not responding..

Anyway, here's my reply:

My Web Server environment are Windows 7 for development (4 GB Ram and i5 processor) 
and Windows Server 2008 R2 
(Virtual PC with 2 GB Ram and i7 processor) for other deployment testing.

Yes I believe we need to minimize the startup delay but I'm more concerned with the 
initial query and saving process because in the eyes of the client they will thought
that the system is slow when retrieving data.

There's a problem in the initial query, because I'm tracing this using trace viewer 
and sql profiler, the Devforce query is executed on 2011-10-10T16:32:53 and ended in 
2011-10-10T16:33:02 and after that the "Real Data Retrieval" happened.

This is also true to the Save Process, it happened more or less 2011-10-10T16:33:10
or 2011-10-10T16:33:11 because I change field value and hit the save button w/c
actually calls the context.SaveChanges() and ended up 2011-10-10T16:33:16, 
note that I only changed one field here.

I'm really after with query and save operation because this is where the client
interaction would take place, we could handle the startup by creating some splash 
screen or other techniques but we also want to minimize it.

Thanks,
Von

Posted By: kimj
Date Posted: 11-Oct-2011 at 9:45am
Hi Von,
 
OK, since you're on a a development machine the initial startup is probably not a concern.
 
The problem is that you're running a distributed application and this is the log from the server.  This log shows the server receiving the query at 16:32:53.  I can't tell when the query completes because I then see creation of a communication proxy, which should not be here.   Creation of that proxy is happening in the gap from 16:32:54 to 16:33:02, so I have to assume it's this causing the performance hit here.   Your application is creating a new EntityManager somewhere, likely in the custom query interceptor, which is causing this to happen.  Once we resolve this then we can see what else is happening with the first query and if that performance can be improved.
 
On the save, the server doesn't receive the save request until 16:33:15.  If your client application called SaveChanges at 16:33:11 then we need to understand what was happening between this call on the client and the time the request hit the server.  Do you have client-side event handlers in place?  What is your save interceptor doing?  What kind of validations are in place?  Additional diagnostics in your save interceptor may help here.
 
When you make a change to one property and then save the entity, the entire entity is still sent to the server.  Since you're saving only one entity it's unlikely the payload is large, but if that entity has byte arrays or large text fields then transmission could certainly be slower than you might expect.   Instance-level validation will also be performed on the entity during save processing, so check which verifiers will be running.
 
I should emphasize also that you'll always see delays (usually small) when the services first start, and upon the first query and save to hit the server.  This does mean that the unlucky user who experienced these will see some slowness, but not every user for every first query and save.  Once the BOS is humming along there will be no further initialization by either DevForce or EF. 
 
For further help, email to IdeaBladeSupportTrack, your client and server debug logs, the code from your custom login manager, the query and save interceptors, your EDMX, and any custom verifiers or buddy classes which add verifiers.  If it's easier, you can instead send a repro solution which exhibits these issues.
 
Kim
 
 


Print Page | Close Window