High latency problem is often found in logs

[Andrei]

I'm using the latest internal build 2012.2.517.3 on an Intel i7 (4 cores) laptop with 6GB.
The solution I'm working on is pretty large (286 projects, lots of interfaces, Edmx's, WinForm's) and during the day VS memory usage reaches about 1.1 - 1.2 Gb. The code analysis process would normally reach ~400Mb but may drop to 200 or even a few megs during idle periods.

The system has about 5 - 5.1Gb memory allocated with about 1Gb available.

I have to say the whole setup is still pretty usable, however, sometimes you can notice some delays like, for example, what I had described in another thread called 'Smart semicolon often lags behind'.

But what I've also noticed is that there are multiple records in the log file mentioning high latency of certain operations, for instance:

SILENT 2012-05-30 12:01:51.509 : High latency: Handling SelectionContextCommandAvailability elapsed 225
SILENT 2012-05-30 12:01:54.749 : High latency: Handling GotoSymbolDialogData elapsed 293
SILENT 2012-05-30 12:01:54.869 : High latency: Handling GotoSymbolDialogData elapsed 119
SILENT 2012-05-30 12:02:51.024 : High latency: Handling IntroduceParameterData elapsed 25867
SILENT 2012-05-30 12:02:51.024 : High latency: Handling engine data took 99.38 % of last 26.0 seconds
SILENT 2012-05-30 12:02:51.040 :    IntroduceParameterData => 99.37 %
SILENT 2012-05-30 12:02:51.040 :    EngineBusyData => 0.00 %
SILENT 2012-05-30 12:03:15.829 : High latency: Handling IntroduceParameterData elapsed 5958
SILENT 2012-05-30 12:03:15.858 : High latency: Handling engine data took 98.95 % of last 6.0 seconds
SILENT 2012-05-30 12:03:15.858 :    IntroduceParameterData => 98.94 %
SILENT 2012-05-30 12:03:15.859 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 12:04:18.676 : High latency: Handling IntroduceParameterData elapsed 5147
SILENT 2012-05-30 12:04:18.676 : High latency: Handling engine data took 98.69 % of last 5.2 seconds
SILENT 2012-05-30 12:04:18.676 :    IntroduceParameterData => 98.67 %
SILENT 2012-05-30 12:04:18.676 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 12:04:31.160 : High latency: Handling FindResultsWindowData elapsed 648
SILENT 2012-05-30 12:04:31.160 : High latency: Handling engine data took 66.49 % of last 1.1 seconds
SILENT 2012-05-30 12:04:31.160 :    FindResultsWindowData => 60.35 %
SILENT 2012-05-30 12:04:31.160 :    SearchProgressPopupData => 6.10 %
SILENT 2012-05-30 12:04:31.160 :    EngineBusyData => 0.04 %
SILENT 2012-05-30 12:05:26.565 : High latency: Handling IntroduceParameterData elapsed 16763
SILENT 2012-05-30 12:05:26.566 : High latency: Handling engine data took 99.64 % of last 16.8 seconds
SILENT 2012-05-30 12:05:26.566 :    IntroduceParameterData => 99.63 %
SILENT 2012-05-30 12:05:26.566 :    EngineBusyData => 0.00 %
SILENT 2012-05-30 12:05:48.269 : High latency: Handling FindResultsWindowData elapsed 152
SILENT 2012-05-30 12:06:37.684 : High latency: Handling IntroduceParameterData elapsed 11379
SILENT 2012-05-30 12:06:37.684 : High latency: Handling engine data took 99.39 % of last 11.4 seconds
SILENT 2012-05-30 12:06:37.684 :    IntroduceParameterData => 99.38 %
SILENT 2012-05-30 12:06:37.684 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 12:11:37.102 : High latency: Handling IntroduceParameterData elapsed 6590
SILENT 2012-05-30 12:11:37.102 : High latency: Handling engine data took 99.21 % of last 6.6 seconds
SILENT 2012-05-30 12:11:37.102 :    IntroduceParameterData => 99.20 %
SILENT 2012-05-30 12:11:37.102 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 12:12:17.825 : High latency: Handling IntroduceParameterData elapsed 4652
SILENT 2012-05-30 12:12:17.826 : High latency: Handling engine data took 98.62 % of last 4.7 seconds
SILENT 2012-05-30 12:12:17.826 :    IntroduceParameterData => 98.60 %
SILENT 2012-05-30 12:12:17.826 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 12:12:38.012 : High latency: Handling IntroduceParameterData elapsed 7191
SILENT 2012-05-30 12:12:38.012 : High latency: Handling engine data took 99.19 % of last 7.3 seconds
SILENT 2012-05-30 12:12:38.012 :    IntroduceParameterData => 99.18 %
SILENT 2012-05-30 12:12:38.013 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 12:23:14.132 : High latency: Handling SearchApiPopupData elapsed 264
SILENT 2012-05-30 12:32:41.280 : High latency: Handling IntroduceParameterData elapsed 5861
SILENT 2012-05-30 12:32:41.281 : High latency: Handling engine data took 98.86 % of last 5.9 seconds
SILENT 2012-05-30 12:32:41.281 :    IntroduceParameterData => 98.85 %
SILENT 2012-05-30 12:32:41.281 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 13:06:38.175 : High latency: Handling IntroduceParameterData elapsed 6970
SILENT 2012-05-30 13:06:38.176 : High latency: Handling engine data took 99.03 % of last 7.0 seconds
SILENT 2012-05-30 13:06:38.176 :    IntroduceParameterData => 99.02 %
SILENT 2012-05-30 13:06:38.176 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 13:07:47.179 : High latency: Handling IntroduceParameterData elapsed 4535
SILENT 2012-05-30 13:07:47.179 : High latency: Handling engine data took 98.67 % of last 4.6 seconds
SILENT 2012-05-30 13:07:47.179 :    IntroduceParameterData => 98.66 %
SILENT 2012-05-30 13:07:47.179 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 13:08:13.765 : High latency: Handling IntroduceParameterData elapsed 5848
SILENT 2012-05-30 13:08:13.765 : High latency: Handling engine data took 98.76 % of last 5.9 seconds
SILENT 2012-05-30 13:08:13.766 :    IntroduceParameterData => 98.75 %
SILENT 2012-05-30 13:08:13.766 :    EngineBusyData => 0.01 %
SILENT 2012-05-30 13:18:16.787 : High latency: Handling EngineBusyData elapsed 187

Can you comment on this?
Also I'm wondering if you guys tested JustCode on solutions comparable in size to mine?

[Svetlozar]

Hello,

Thank you for your feedback!

The High Latency log entries are simply debug messages. JustCode uses an external process for its analysis and an addin for the Visual Studio integration. We measure the time it takes for the UI part to perform a communication operation. Your log seems fine. The IntroduceParamataData log entries might seem problematic, but it is expected as Introduce Parameter opens a modal dialog. You shouldn't worry about these entries.

Also I'm wondering if you guys tested JustCode on solutions comparable in size to mine?
Yes, we do all kinds of tests on different sized projects. Additionally we often release builds in the company and Telerik has some quite large solutions. Based on our observations the resources JustCode takes on your side are in the expected range. Of course we are constantly working on performance and memory optimizations, so if you observe any slowness or suspicious memory usage, please let us know.
Greetings,
Svetlozar
the Telerik team