Add some profilling information for loading a project

All this information goes to its own file.

FEA: ItEr74S08DeployFramework

ganttzk/src/main/java/org/zkoss/ganttz/Planner.java

@@ -33,6 +33,7 @@ import java.util.Map;
 import java.util.Map.Entry;
 import java.util.Set;
 
+import org.apache.commons.logging.Log;
 import org.zkoss.ganttz.adapters.IDisabilityConfiguration;
 import org.zkoss.ganttz.adapters.IDomainAndBeansMapper;
 import org.zkoss.ganttz.adapters.PlannerConfiguration;
@@ -52,7 +53,7 @@ import org.zkoss.ganttz.timetracker.zoom.ZoomLevel;
 import org.zkoss.ganttz.util.ComponentsFinder;
 import org.zkoss.ganttz.util.LongOperationFeedback;
 import org.zkoss.ganttz.util.LongOperationFeedback.ILongOperation;
-import org.zkoss.ganttz.util.OnZKDesktopRegistry;
+import org.zkoss.ganttz.util.ProfilingLogFactory;
 import org.zkoss.ganttz.util.WeakReferencedListeners;
 import org.zkoss.ganttz.util.WeakReferencedListeners.IListenerNotification;
 import org.zkoss.zk.au.AuRequest;
@@ -76,6 +77,9 @@ import org.zkoss.zul.South;
 
 public class Planner extends HtmlMacroComponent  {
 
+    private static final Log PROFILING_LOG = ProfilingLogFactory
+            .getLog(Planner.class);
+
     public static boolean guessContainersExpandedByDefaultGivenPrintParameters(
             Map<String, String> printParameters) {
         return guessContainersExpandedByDefault(convertToURLParameters(printParameters));
@@ -325,9 +329,12 @@ public class Planner extends HtmlMacroComponent  {
         this.context = newContext;
         this.disabilityConfiguration = configuration;
         resettingPreviousComponentsToNull();
+        long timeAddingData = System.currentTimeMillis();
         newContext.add(configuration.getData());
+        PROFILING_LOG.info("It took to add data: "
+                + (System.currentTimeMillis() - timeAddingData) + " ms");
+        long timeSetupingAndAddingComponents = System.currentTimeMillis();
         setupComponents();
-
         setAt("insertionPointLeftPanel", leftPane);
         leftPane.afterCompose();
         setAt("insertionPointRightPanel", ganttPanel);
@@ -366,6 +373,11 @@ public class Planner extends HtmlMacroComponent  {
         this.visibleChart = configuration.isExpandPlanningViewCharts();
         ((South) getFellow("graphics")).setOpen(this.visibleChart);
 
+        PROFILING_LOG
+                .info("it took doing the setup of components and adding them: "
+                        + (System.currentTimeMillis() - timeSetupingAndAddingComponents)
+                        + " ms");
+
         setAuService(new AuService(){
             public boolean service(AuRequest request, boolean everError){
                 String command = request.getCommand();

ganttzk/src/main/java/org/zkoss/ganttz/util/ProfilingLogFactory.java

@@ -0,0 +1,46 @@
+/*
+ * This file is part of NavalPlan
+ *
+ * Copyright (C) 2011 Igalia, S.L.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ */
+package org.zkoss.ganttz.util;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+
+/**
+ * Equivalent to {@link LogFactory}. Use when logging profiling information.
+ *
+ * @author Óscar González Fernández <ogonzalez@igalia.com>
+ */
+public class ProfilingLogFactory {
+
+    /**
+     * Use this method instead of {@link LogFactory#getLog(Class)} in order to
+     * get a {@link Log} that logs to a specific log for profiling.
+     *
+     * @param klass
+     * @return a normal instance of a {@link Log} object with starting with the
+     *         profiling string.
+     */
+    public static Log getLog(Class<?> klass) {
+        return LogFactory.getLog("profiling." + klass.getName());
+    }
+
+    private ProfilingLogFactory() {
+    }
+
+}

navalplanner-webapp/src/main/java/org/navalplanner/web/planner/order/OrderPlanningController.java

@@ -32,6 +32,7 @@ import java.util.Map;
 import java.util.Map.Entry;
 
 import org.apache.commons.lang.Validate;
+import org.apache.commons.logging.Log;
 import org.navalplanner.business.orders.entities.Order;
 import org.navalplanner.business.planner.entities.TaskElement;
 import org.navalplanner.web.common.ViewSwitcher;
@@ -57,7 +58,7 @@ import org.zkoss.ganttz.extensions.IContextWithPlannerTask;
 import org.zkoss.ganttz.timetracker.zoom.ZoomLevel;
 import org.zkoss.ganttz.util.LongOperationFeedback;
 import org.zkoss.ganttz.util.LongOperationFeedback.ILongOperation;
-import org.zkoss.ganttz.util.OnZKDesktopRegistry;
+import org.zkoss.ganttz.util.ProfilingLogFactory;
 import org.zkoss.zk.ui.Executions;
 import org.zkoss.zk.ui.WrongValueException;
 import org.zkoss.zk.ui.util.Composer;
@@ -73,6 +74,9 @@ import org.zkoss.zul.Vbox;
 @Scope(BeanDefinition.SCOPE_PROTOTYPE)
 public class OrderPlanningController implements Composer {
 
+    private static final Log PROFILING_LOG = ProfilingLogFactory
+            .getLog(OrderPlanningController.class);
+
     @Autowired
     private ViewSwitcher viewSwitcher;
 
@@ -186,10 +190,13 @@ public class OrderPlanningController implements Composer {
 
     private void updateConfiguration() {
         if (order != null) {
+            long time = System.currentTimeMillis();
             model.setConfigurationToPlanner(planner, order, viewSwitcher,
                     editTaskController, advanceAssignmentPlanningController,
                     advanceConsolidationController,
                     calendarAllocationController, additional);
+            PROFILING_LOG.info("setConfigurationToPlanner took: "
+                    + (System.currentTimeMillis() - time) + " ms");
             planner.updateSelectedZoomLevel();
             showResorceAllocationIfIsNeeded();
         }

navalplanner-webapp/src/main/java/org/navalplanner/web/planner/order/OrderPlanningModel.java

@@ -139,6 +139,7 @@ import org.zkoss.ganttz.timetracker.zoom.IZoomLevelChangedListener;
 import org.zkoss.ganttz.timetracker.zoom.SeveralModificators;
 import org.zkoss.ganttz.timetracker.zoom.ZoomLevel;
 import org.zkoss.ganttz.util.Interval;
+import org.zkoss.ganttz.util.ProfilingLogFactory;
 import org.zkoss.zk.ui.Executions;
 import org.zkoss.zk.ui.WrongValueException;
 import org.zkoss.zk.ui.event.Event;
@@ -175,6 +176,9 @@ public abstract class OrderPlanningModel implements IOrderPlanningModel {
 
     private static final Log LOG = LogFactory.getLog(OrderPlanningModel.class);
 
+    private static final Log PROFILING_LOG = ProfilingLogFactory
+            .getLog(OrderPlanningModel.class);
+
     public static <T extends Collection<Resource>> T loadRequiredDataFor(
             T resources) {
         for (Resource each : resources) {
@@ -362,9 +366,12 @@ public abstract class OrderPlanningModel implements IOrderPlanningModel {
             AdvanceConsolidationController advanceConsolidationController,
             CalendarAllocationController calendarAllocationController,
             List<ICommand<TaskElement>> additional) {
+        long time = System.currentTimeMillis();
         currentScenario = scenarioManager.getCurrent();
         orderReloaded = reload(order);
         PlannerConfiguration<TaskElement> configuration = createConfiguration(planner, orderReloaded);
+        PROFILING_LOG.info("load data and create configuration took: "
+                + (System.currentTimeMillis() - time) + " ms");
         User user;
         try {
             user = this.userDAO.findByLoginName(SecurityUtils
@@ -374,7 +381,6 @@ public abstract class OrderPlanningModel implements IOrderPlanningModel {
         }
         configuration.setExpandPlanningViewCharts(user
                 .isExpandOrderPlanningViewCharts());
-
         addAdditional(additional, configuration);
 
         ZoomLevel defaultZoomLevel = OrderPlanningModel
@@ -419,8 +425,11 @@ public abstract class OrderPlanningModel implements IOrderPlanningModel {
 
         configuration.setChartComponent(chartComponent);
         configureModificators(orderReloaded, configuration);
+        long setConfigurationTime = System.currentTimeMillis();
         planner.setConfiguration(configuration);
-
+        PROFILING_LOG.info("setConfiguration on planner took: "
+                + (System.currentTimeMillis() - setConfigurationTime) + " ms");
+        long preparingChartsAndMisc = System.currentTimeMillis();
         // Prepare tabpanels
         Tabpanels chartTabpanels = new Tabpanels();
 
@@ -447,10 +456,17 @@ public abstract class OrderPlanningModel implements IOrderPlanningModel {
                 planner, changeHooker);
         setupOverallProgress(planner, changeHooker);
         setupAdvanceAssignmentPlanningController(planner, advanceAssignmentPlanningController);
+        PROFILING_LOG
+                .info("preparing charts and miscellaneous took: "
+                        + (System.currentTimeMillis() - preparingChartsAndMisc)
+                        + " ms");
 
         planner.addGraphChangeListenersFromConfiguration(configuration);
+        long overalProgressContentTime = System.currentTimeMillis();
         overallProgressContent = new OverAllProgressContent(overallProgressTab);
         overallProgressContent.updateAndRefresh();
+        PROFILING_LOG.info("overalProgressContent took: "
+                + (System.currentTimeMillis() - overalProgressContentTime));
     }
 
     private void setupAdvanceAssignmentPlanningController(final Planner planner,

navalplanner-webapp/src/main/resources/log4j.xml

@@ -31,6 +31,19 @@
     </filter>
   </appender>
 
+  <appender name="rolling-profiling" class="org.apache.log4j.DailyRollingFileAppender">
+    <param name="file" value="${navalplan-log-directory}navalplan-profile.log" />
+    <param name="datePattern" value="'.'yyyy-MM-dd" /> <!-- Rollover each midnight -->
+
+    <layout class="org.apache.log4j.PatternLayout">
+      <param name="ConversionPattern" value="%-5p [%d{dd-MMMM HH:mm:ss}] [%t] %c %x - %m%n" />
+    </layout>
+
+    <filter class="org.apache.log4j.varia.LevelRangeFilter">
+      <param name="levelMin" value="INFO" />
+    </filter>
+  </appender>
+
   <appender name="ASYNC" class="org.apache.log4j.AsyncAppender">
     <param name="BufferSize" value="1000" />
     <appender-ref ref="console" />
@@ -38,8 +51,19 @@
     <appender-ref ref="rolling-errors" />
   </appender>
 
+  <appender name="ASYNC-profiling" class="org.apache.log4j.AsyncAppender">
+    <param name="BufferSize" value="1000" />
+    <appender-ref ref="rolling-profiling" />
+    <appender-ref ref="console" />
+  </appender>
+
+  <logger name="profiling" additivity="false">
+    <level value="info" />
+    <appender-ref ref="ASYNC-profiling" />
+  </logger>
+
   <root>
     <priority value="info" />
     <appender-ref ref="ASYNC" />
   </root>
-</log4j:configuration>
+</log4j:configuration>