High latency problem is often found in logs

2 posts, 0 answers
  1. Andrei
    Andrei avatar
    30 posts
    Member since:
    May 2012

    Posted 30 May 2012 Link to this post

    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?
  2. Svetlozar
    Admin
    Svetlozar avatar
    269 posts

    Posted 01 Jun 2012 Link to this post

    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

    Explore the entire Telerik portfolio by downloading the Ultimate Collection trial package. Get it now >>

  3. DevCraft banner
Back to Top