This website uses cookies for visitor traffic analysis. By using the website, you agree with storing the cookies on your computer.More information

Vaadin, let's hack the Profiler

Vaadin comes with a builtin Profiler which is only available during debug mode, which might not be available or reasonable. So, let us see if we can use it without the debug mode enabled.

It has a profiler?

Yes, there is one right builtin on the client side. You can activate it easily enough by adding the following to the widgetset:

  1. <set-property name="vaadin.profiler" value="true" />

But to see the results, you also have to switch the application into debug mode by changing the web.xml to the following:

  1. <context-param>
  2.     <description>Vaadin production mode</description>
  3.     <param-name>productionMode</param-name>
  4.     <param-value>false</param-value>
  5. </context-param>

This allows you to enter the debug mode of an application, though, that requires to restart the application (or in the worst case, a redeploy). One upside of testing new Widgetsets can be that one can apply them to any running application without modifications, because that is purely client-side. So changing the configuration of the application might not be possible or desirable.

There are some forum posts out there which talk about that it is enough to enable the profiler and see the the output of it being logged to the debug console of the browser, but that is not the case anymore.

Let's have a deeper look

The Profiler can be found in the class com.vaain.vaadin.client.Profiler and is comletely client-side. It will store all gathered information until the function logTimings() is called, which then will hand the gathered information to a consumer which can do with it whatever it wants. Now comes the interesting part, there is no public default implementation for the consumer provided. If you want to log what was profiled to the debug console you'll have to write your own. Even if there were, the function setProfilerResultConsumer(ProfilerResultConsumer) is commented with a warning that it might change in future versions without notice and should not be used - interesting. Also interesting is the fact that it can only be set once. Once set, it can not be changed.

Hm, looks a little bare bone. Of course there is an "internal" class that is utilizing it to send its output to the debug window, but we can't use any of that code, unfortunately. So let's see what we can do with it.

Send everything to the debug console

The easiest thing is to simply send all the output to the debug console of the browser, we can do this easily enough:

  1. import java.util.LinkedHashMap;
  2. import java.util.List;
  3.  
  4. import com.vaadin.client.Profiler.Node;
  5. import com.vaadin.client.Profiler.ProfilerResultConsumer;
  6.  
  7. /**
  8.  * A simple {@link ProfilerResultConsumer} which is outputting everything to the
  9.  * debug console of the browser.
  10.  *
  11.  * @author Robert Zenz
  12.  */
  13. public class DebugConsoleProfilerResultConsumer implements ProfilerResultConsumer
  14. {
  15.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  16.     // Initialization
  17.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  18.    
  19.     /**
  20.      * Creates a new instance of {@link DebugConsoleProfilerResultConsumer}.
  21.      */
  22.     public DebugConsoleProfilerResultConsumer()
  23.     {
  24.         super();
  25.     }
  26.    
  27.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  28.     // Interface implementation
  29.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  30.    
  31.     /**
  32.      * {@inheritDoc}
  33.      */
  34.     @Override
  35.     public void addProfilerData(Node pRootNode, List pTotals)
  36.     {
  37.         debug(pRootNode);
  38.        
  39.         for (Node node : pTotals)
  40.         {
  41.             debug(node);
  42.         }
  43.     }
  44.    
  45.     /**
  46.      * {@inheritDoc}
  47.      */
  48.     @Override
  49.     public void addBootstrapData(LinkedHashMap pTimings)
  50.     {
  51.         // TODO We'll ingore this for now.
  52.     }
  53.    
  54.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  55.     // User-defined methods
  56.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  57.    
  58.     /**
  59.      * Sends the given {@link Node} to the debug console if it is
  60.      * {@link #isValid(Node) valid}.
  61.      *
  62.      * @param pNode the {@link Node} to log.
  63.      * @see #isValid(Node)
  64.      */
  65.     private void debug(Node pNode)
  66.     {
  67.         if (isValid(pNode))
  68.         {
  69.             debug(pNode.getStringRepresentation(""));
  70.         }
  71.     }
  72.    
  73.     /**
  74.      * Tests if the given {@link Node} is valid, meaning not {@code null}, has a
  75.      * {@link Node#getName() name} and was {@link Node#getCount() invoked at
  76.      * all}.
  77.      *
  78.      * @param pNode the {@link Node} to test}.
  79.      * @return {@code true} if the given {@link Node} is considered valid.
  80.      */
  81.     private boolean isValid(Node pNode)
  82.     {
  83.         return pNode != null && pNode.getName() != null && pNode.getCount() > 0;
  84.     }
  85.    
  86.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  87.     // Native methods
  88.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  89.    
  90.     /**
  91.      * Logs the given message to the debug console.
  92.      *
  93.      * @param pMessage the message to log.
  94.      */
  95.     private native void debug(String pMessage)
  96.     /*-{
  97.         console.debug(pMessage);
  98.     }-*/;
  99.    
  100. }    // DebugConsoleProfilerResultConsumer

And we can attach it rather easily, too:

  1. Profiler.setProfilerResultConsumer(new DebugConsoleProfilerResultConsumer());

Make sure to do this only once, otherwise an Exception will be thrown, stating that it can only be done once. Also the application should not be in debug mode, otherwise the Vaadin consumer will be attached. Now that we've attached a consumer we can recompile the Widgetset and actually try it, and low and behold, we see output in the debug window of the browser. Quite a lot, actually, seems like the Profiler is used often, which is good.

Filter the results

Skimming through the results is tedious, luckily most browsers come with the possibility to filter the results, but that possibility is quite limited. If we are interested in multiple results, the easiest way will be to filter them on the server side, obviously we can do that just as easily:

  1. import java.util.HashSet;
  2. import java.util.LinkedHashMap;
  3. import java.util.List;
  4. import java.util.Set;
  5.  
  6. import com.vaadin.client.Profiler.Node;
  7. import com.vaadin.client.Profiler.ProfilerResultConsumer;
  8.  
  9. /**
  10.  * A simple {@link ProfilerResultConsumer} which is outputting everything to the
  11.  * debug console of the browser.
  12.  *
  13.  * @author Robert Zenz
  14.  */
  15. public class DebugConsoleProfilerResultConsumer implements ProfilerResultConsumer
  16. {
  17.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  18.     // Class members
  19.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  20.    
  21.     /** The names of nodes we want to output. */
  22.     private Set wantedNames = new HashSet();
  23.    
  24.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  25.     // Initialization
  26.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  27.    
  28.     /**
  29.      * Creates a new instance of {@link DebugConsoleProfilerResultConsumer}.
  30.      *
  31.      * @param pWantedNames the names of the profiler data which should be
  32.      *            displayed.
  33.      */
  34.     public DebugConsoleProfilerResultConsumer(String... pWantedNames)
  35.     {
  36.         super();
  37.        
  38.         if (pWantedNames != null && pWantedNames.length > 0)
  39.         {
  40.             for (String wantedName : pWantedNames)
  41.             {
  42.                 wantedNames.add(wantedName);
  43.             }
  44.         }
  45.     }
  46.    
  47.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  48.     // Interface implementation
  49.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  50.    
  51.     /**
  52.      * {@inheritDoc}
  53.      */
  54.     @Override
  55.     public void addProfilerData(Node pRootNode, List pTotals)
  56.     {
  57.         debug(pRootNode);
  58.        
  59.         for (Node node : pTotals)
  60.         {
  61.             debug(node);
  62.         }
  63.     }
  64.    
  65.     /**
  66.      * {@inheritDoc}
  67.      */
  68.     @Override
  69.     public void addBootstrapData(LinkedHashMap pTimings)
  70.     {
  71.         // TODO We'll ingore this for now.
  72.     }
  73.    
  74.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  75.     // User-defined methods
  76.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  77.    
  78.     /**
  79.      * Sends the given {@link Node} to the debug console if it is
  80.      * {@link #isValid(Node) valid}.
  81.      *
  82.      * @param pNode the {@link Node} to log.
  83.      * @see #isValid(Node)
  84.      */
  85.     private void debug(Node pNode)
  86.     {
  87.         if (isValid(pNode))
  88.         {
  89.             debug(pNode.getStringRepresentation(""));
  90.         }
  91.     }
  92.    
  93.     /**
  94.      * Tests if the given {@link Node} is valid, meaning not {@code null}, has a
  95.      * {@link Node#getName() name} and was {@link Node#getCount() invoked at
  96.      * all}.
  97.      *
  98.      * @param pNode the {@link Node} to test}.
  99.      * @return {@code true} if the given {@link Node} is considered valid.
  100.      */
  101.     private boolean isValid(Node pNode)
  102.     {
  103.         return pNode != null
  104.                 && pNode.getName() != null
  105.                 && pNode.getCount() > 0
  106.                 && (wantedNames.isEmpty() || wantedNames.contains(pNode.getName()));
  107.     }
  108.    
  109.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  110.     // Native methods
  111.     //~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  112.    
  113.     /**
  114.      * Logs the given message to the debug console.
  115.      *
  116.      * @param pMessage the message to log.
  117.      */
  118.     private native void debug(String pMessage)
  119.     /*-{
  120.         console.debug(pMessage);
  121.     }-*/;
  122.    
  123. }    // DebugConsoleProfilerResultConsumer

Now we can simply pass the list of "interesting" event names to the consumer and see only these.

JavaScript hacking

But there is more, instead of setting a consumer we can attach ourselves to the JavaScript function and instead process each profiled section individually. So in the debug console we can simply run something like this:

  1. window.__gwtStatsEvent = function(event)
  2. {
  3.     console.debug(event);
  4. };

This will output every single profiler event into the console. Now, if we want to process these events, we must first understand there is always a "begin" and an "end" event, which respectively are marking the begin and end of an event.

We can now listen for a certain event and simply output how long it took, like this:

  1. window.__profiler = {};
  2.  
  3. window.__gwtStatsEvent = function(event)
  4. {
  5.     if (event.subSystem === "Layout pass")
  6.     {
  7.         if (event.type === "begin")
  8.         {
  9.             window.__profiler[event.subSystem] = event.millis;
  10.         }
  11.         else
  12.         {
  13.             console.log(
  14.                     event.subSystem
  15.                     + ": "
  16.                     + (event.millis - window.__profiler[event.subSystem]).toFixed(0)
  17.                     + "ms");
  18.         }
  19.     }
  20. };

Or, to go over the top, we could create a generic listener which informs us about everything:

  1. window.__wantedEvents = [
  2.     "Layout pass",
  3.     "Layout measure connectors",
  4.     "layout PostLayoutListener"
  5. ];
  6.  
  7. window.__profiler = {};
  8.  
  9. window.__gwtStatsEvent = function(event)
  10. {
  11.     if (window.__wantedEvents.indexOf(event.subSystem) >= 0)
  12.     {
  13.         if (typeof window.__profiler[event.subSystem] === "undefined")
  14.         {
  15.             window.__profiler[event.subSystem] = {
  16.                 averageRuntime : 0,
  17.                 count : 0,
  18.                 lastBegin : 0,
  19.                 lastEnd : 0,
  20.                 lastRuntime: 0,
  21.                 lastRuntimes : new Array(),
  22.                 minRuntime : 999999999,
  23.                 maxRuntime : -999999999,
  24.                 totalRuntime : 0
  25.             }
  26.         }
  27.        
  28.         var info = window.__profiler[event.subSystem];
  29.        
  30.         if (event.type === "begin")
  31.         {
  32.             info.count = info.count + 1;
  33.             info.lastBegin = event.millis;
  34.         }
  35.         else
  36.         {
  37.             info.lastEnd = event.millis;
  38.            
  39.             info.lastRuntime = info.lastEnd - info.lastBegin;
  40.             info.lastRuntimes.push(info.lastRuntime);
  41.             info.minRuntime = Math.min(info.lastRuntime, info.minRuntime);
  42.             info.maxRuntime = Math.max(info.lastRuntime, info.maxRuntime);
  43.             info.totalRuntime = info.totalRuntime + info.lastRuntime;
  44.            
  45.             info.averageRuntime = 0;
  46.             for (var index = 0; index < info.lastRuntimes.length; index++)
  47.             {
  48.                 info.averageRuntime = info.averageRuntime + info.lastRuntimes[index];
  49.             }
  50.             info.averageRuntime = info.averageRuntime / info.lastRuntimes.length;
  51.            
  52.             console.log(
  53.                     event.subSystem
  54.                     + ": "
  55.                     + info.count.toFixed(0)
  56.                     + " times at "
  57.                     + info.averageRuntime.toFixed(3)
  58.                     + " totaling "
  59.                     + info.totalRuntime.toFixed(0)
  60.                     + "ms with current at "
  61.                     + info.lastRuntime.toFixed(0)
  62.                     + "ms ("
  63.                     + info.minRuntime.toFixed(0)
  64.                     + "ms/"
  65.                     + info.maxRuntime.toFixed(0)
  66.                     + "ms)");
  67.         }
  68.     }
  69. };

And we now have a neat little system in place which displays everything we'd like to know, and it is easily extendable and modifiable, too.

Conclusion

As we see, we have quite a few ways to get the information from the profiler even without the application running in debug mode, some might not be as obvious as others, though. The interesting part is that many things are easily accessible on the JavaScript side of Vaadin, directly from the debug console of the browser, one only has to look for it.

categories Information | rzenz | 11/09/2017 | comments Comments (0)

categories

© SIB Visions GmbH