Announcement

Collapse
No announcement yet.
X
  • Filter
  • Time
Clear All
new posts

    Calls to logDebug() found when dev console is not open

    Hello,

    I've been investigating some performance issues with our application. When a user is doing repetitive data entry, their performance is gradually degrading after 20-30 consecutive edits. Initially, performance is very adequate with each operation taking less than 1 second despite interaction with the server and multiple calculations occurring in the callback from the server. However, as the edits progress, we are noting performance degrading very gradually but significantly so that it takes nearly 10 seconds to do the same operation that initially took 1 second.

    We've inserted extensive debug logic to determine this is in fact a client-side issue and not related to server interactions. The slowdown is in the client-side callback. So, I've been using Firebug's profiler to try to better pinpoint the slowdown.

    We are still sifting through our logic and trying to refine our investigation. But, one thing pops out as a significant difference between one of the early fast callbacks and the later slow callbacks. That is calls to logDebug() being reported by firebug profiler. They are taking an order of magnitude more processing time in the slow callbacks.

    I am a bit confused by this because we are in fact using logInfo() for all of our logging to the dev console. We are not using logDebug() anywhere. And, these calls to logDebug are being reported by firebug profiler even when the dev console is closed.

    So, are you able to help me understand why logDebug is getting called when we are not explicity calling logDebug() and the dev console is not even open? Is it possible there are some calls to logDebug() in your codebase that are not wrapped in recommended logic to check to logIsDebugEnabled() that could be impacting our performance as the user's session progresses? We are using 6.5.1.

    Thanks for the help.

    #2
    It's not particularly plausible that logDebug() in particular would be slow. Logs can be very slow if the messages take a while to prepare (eg echoAll() on a large structure), but if so, this would not be shown as a slow call to logDebug(), because the log message is prepared before logDebug() is called. You would see the increased time instead in the method that calls logDebug().

    If you enable log at debug level for both "gridEdit" and "ListGrid" when you do one of the interactions that appears slow, do you see anything you are not seeing with these two categories set to a normal threshold (eg WARN)?

    Comment


      #3
      Hi, if you are asking if I see anything different in Firebug profiler when changing the logging for "gridEdit" and "listGrid" to debug, the answer is no. However, looking at my profilers output more, I don't really think that logDebug itself is the issue either. It really just struck me as odd that we were seeing logDebug() show up at all.

      So, am I correct that if the following conditions exist, logDebug should not be called at all?
      1. None of my categories are set to debug in the dev console.
      2. my dev console is in fact NOT open at all.
      3. We have no code that is calling logDebug()

      It seems to me that if those 3 conditions are met, then logDebug shouldn't get called. But, Firebug profile is telling me that logDebug is still getting called thousands of times for this interaction. So, is that perhaps some logic in your codebase that still needs to be wrapped inside of the logIsDebugEnabled() check that you recommend in your debugging topic?

      Back to our performance issues, I do see that a function called qy() is the slowest function for the slow interaction. It exists in the core file on line 2393. It gets called 160 times and takes 550 ms to execute those 160 calls. On the other hand, it gets called 85 times and takes 103 ms to executes those 83 calls for a fast interaction before the performance problems start.

      Would you be willing to share what this function does? Perhaps just a helper in ListGrid cell formatting? It may help me as I track down what is slowing down our code.And, I wanted to point it out to see if it surprised you to see it slowing down so much as time progresses?

      Here is the code for qy():
      Code:
      function () {
          var _1 = this.getHandle();
          if (isc.Browser.isOpera) {
              var _1 = this.getHandle();
              return !(_1.scrollHeight == 0 && _1.scrollWidth == 0);
          }
          if (!isc.Browser.isIE) {
              var _2 = this.getClipHandle();
              if (_2 == null) {
                  return false;
              }
              var _3 = _2.scrollHeight;
              if (_3 == null || _3 == 0) {
                  _3 == this.getClipHandle().offsetHeight;
              }
              return _3 != 0;
          }
          var _4;
          if (isc.Browser.isWin) {
              return _1 != null &&
                  _1.scrollHeight != this.$n1 && _1.scrollHeight != 0;
          }
      }
      Thanks for the help.

      Comment


        #4
        Sorry for the belated reply.

        At a very high level, your data seem to indicate lots of grid redraws, some of which may be unnecessary. You can use the "redraws" log, set to DEBUG level, to see the reasons for the redraws (and stack traces on IE). This may reveal an obvious problem.

        Beyond that, this level of analysis isn't really useful without lots of background on what should and shouldn't be expected to take time, and on which browsers. Better to isolate a test case that seems slower than it should be (or slows linearly) and post that.

        Comment


          #5
          Thank you, your suggestion to use the redraws log with IE helps me see clearly what I'd already surmised by more closely reviewing our code. We were calling DynamicForm.editRecord() unnecessarily on each operation. So we added logic to ensure editRecord was only being called when a new record is in fact being edited and not the existing record. This eliminated a lot of extra redraw activity. Not sure why this was causing progressively slower response times? But, regardless, our problem seems resolved.

          Comment


            #6
            Can't explain progressively slower redraw (perhaps some code is searching the list?) but good to hear the issue is resolved.

            Comment

            Working...
            X