Merge branch '193-PerformanceTrace' of https://github.com/maeisabelle/marklogic-data-hub into maeisabelle-193-PerformanceTrace

# Conflicts:
#	marklogic-data-hub/src/main/java/com/marklogic/hub/DataHub.java
#	marklogic-data-hub/src/main/java/com/marklogic/hub/Scaffolding.java

Author: paxtonhare

marklogic-data-hub/src/main/java/com/marklogic/hub/DataHub.java

@@ -15,16 +15,6 @@
  */
 package com.marklogic.hub;
 
-import java.nio.file.Paths;
-import java.util.ArrayList;
-import java.util.HashMap;
-import java.util.List;
-import java.util.Map;
-
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
-import org.springframework.web.client.ResourceAccessException;
-
 import com.fasterxml.jackson.databind.JsonNode;
 import com.marklogic.appdeployer.AppConfig;
 import com.marklogic.appdeployer.ConfigDir;
@@ -46,14 +36,7 @@
 import com.marklogic.appdeployer.command.groups.DeployGroupsCommand;
 import com.marklogic.appdeployer.command.mimetypes.DeployMimetypesCommand;
 import com.marklogic.appdeployer.command.schemas.LoadSchemasCommand;
-import com.marklogic.appdeployer.command.security.DeployAmpsCommand;
-import com.marklogic.appdeployer.command.security.DeployCertificateAuthoritiesCommand;
-import com.marklogic.appdeployer.command.security.DeployCertificateTemplatesCommand;
-import com.marklogic.appdeployer.command.security.DeployExternalSecurityCommand;
-import com.marklogic.appdeployer.command.security.DeployPrivilegesCommand;
-import com.marklogic.appdeployer.command.security.DeployProtectedCollectionsCommand;
-import com.marklogic.appdeployer.command.security.DeployRolesCommand;
-import com.marklogic.appdeployer.command.security.DeployUsersCommand;
+import com.marklogic.appdeployer.command.security.*;
 import com.marklogic.appdeployer.command.tasks.DeployScheduledTasksCommand;
 import com.marklogic.appdeployer.command.triggers.DeployTriggersCommand;
 import com.marklogic.appdeployer.command.viewschemas.DeployViewSchemasCommand;
@@ -68,6 +51,7 @@
 import com.marklogic.client.util.RequestParameters;
 import com.marklogic.hub.commands.LoadHubModulesCommand;
 import com.marklogic.hub.commands.LoadUserModulesCommand;
+import com.marklogic.hub.util.PerformanceLogger;
 import com.marklogic.mgmt.ManageClient;
 import com.marklogic.mgmt.ManageConfig;
 import com.marklogic.mgmt.admin.AdminConfig;
@@ -76,6 +60,15 @@
 import com.marklogic.mgmt.databases.DatabaseManager;
 import com.marklogic.rest.util.Fragment;
 import com.marklogic.rest.util.ResourcesFragment;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.springframework.web.client.ResourceAccessException;
+
+import java.nio.file.Paths;
+import java.util.ArrayList;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
 
 public class DataHub {
 
@@ -109,6 +102,8 @@ private void init(HubConfig hubConfig) {
      * @return true if installed, false otherwise
      */
     public boolean isInstalled() {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
+
         ServerManager sm = new ServerManager(client);
         DatabaseManager dm = new DatabaseManager(client);
 
@@ -156,6 +151,8 @@ public boolean isInstalled() {
                 tracingDbExists && tracingIndexesOn);
         boolean forestsOk = (stagingForestsExist && finalForestsExist && tracingForestsExist);
 
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.isInstalled");
+
         return (appserversOk && dbsOk && forestsOk);
     }
 
@@ -164,6 +161,7 @@ public boolean isInstalled() {
      * @throws ServerValidationException if the server is not compatible
      */
     public void validateServer() throws ServerValidationException {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         try {
             AdminManager am = getAdminManager();
             String versionString = am.getServerVersion();
@@ -176,6 +174,7 @@ public void validateServer() throws ServerValidationException {
         catch(ResourceAccessException e) {
             throw new ServerValidationException(e.toString());
         }
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.validateServer");
     }
 
     private AppConfig getAppConfig() {
@@ -230,14 +229,13 @@ public void updateAppConfig(AppConfig config) {
     }
 
     public void initProject() {
-        long startTime = System.nanoTime();
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         LOGGER.info("Initializing the Hub Project");
 
         HubProject hp = new HubProject(hubConfig);
         hp.init();
-        long endTime = System.nanoTime();
-        long duration = (endTime - startTime);
-        LOGGER.info("Initialize took: " + (duration / 1000000000) + " seconds");
+
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.initProject");
     }
 
     private DatabaseClient getDatabaseClient(int port) {
@@ -255,8 +253,7 @@ private DatabaseClient getDatabaseClient(int port) {
      * Installs User Provided modules into the Data Hub
      */
     public void installUserModules() {
-        long startTime = System.nanoTime();
-
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         LOGGER.debug("Installing user modules into MarkLogic");
 
         List<Command> commands = new ArrayList<Command>();
@@ -266,17 +263,20 @@ public void installUserModules() {
         SimpleAppDeployer deployer = new SimpleAppDeployer(client, getAdminManager());
         deployer.setCommands(commands);
         deployer.deploy(config);
-        long endTime = System.nanoTime();
-        long duration = (endTime - startTime);
-        LOGGER.info("Installing User Modules took: " + (duration / 1000000000) + " seconds");
-
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.installUserModules");
     }
 
     public JsonNode validateUserModules() {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         LOGGER.debug("validating user modules");
+
         DatabaseClient client = getDatabaseClient(hubConfig.stagingPort);
         EntitiesValidator ev = new EntitiesValidator(client);
-        return ev.validate();
+        JsonNode jsonNode = ev.validate();
+
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.validateUserModules");
+
+        return jsonNode;
     }
 
     private List<Command> getCommands(AppConfig config) {
@@ -377,10 +377,9 @@ private AdminManager getAdminManager() {
      * Installs the data hub configuration and server-side modules into MarkLogic
      */
     public void install() {
-
         initProject();
 
-        long startTime = System.nanoTime();
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         LOGGER.info("Installing the Data Hub into MarkLogic");
 
         // clean up any lingering cache for deployed modules
@@ -392,17 +391,16 @@ public void install() {
         deployer.setCommands(getCommands(config));
         deployer.deploy(config);
 
-        long endTime = System.nanoTime();
-        long duration = (endTime - startTime);
-        LOGGER.info("Install took: " + (duration / 1000000000) + " seconds");
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.install");
     }
 
     /**
      * Uninstalls the data hub configuration and server-side modules from MarkLogic
      */
     public void uninstall() {
-        long startTime = System.nanoTime();
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         LOGGER.debug("Uninstalling the Data Hub from MarkLogic");
+
         AppConfig config = getAppConfig();
         SimpleAppDeployer deployer = new SimpleAppDeployer(client, getAdminManager());
         deployer.setCommands(getCommands(config));
@@ -411,9 +409,8 @@ public void uninstall() {
         // clean up any lingering cache for deployed modules
         PropertiesModuleManager moduleManager = new PropertiesModuleManager();
         moduleManager.deletePropertiesFile();
-        long endTime = System.nanoTime();
-        long duration = (endTime - startTime);
-        LOGGER.info("Uninstall took: " + (duration / 1000000000) + " seconds");
+
+        PerformanceLogger.logTimeInsideMethod(startTime, "DataHub.uninstall");
     }
 
     class EntitiesValidator extends ResourceManager {

marklogic-data-hub/src/main/java/com/marklogic/hub/EntityManager.java

@@ -31,6 +31,7 @@
 import com.marklogic.client.util.RequestParameters;
 import com.marklogic.hub.entity.Entity;
 import com.marklogic.hub.entity.EntityImpl;
+import com.marklogic.hub.util.PerformanceLogger;
 
 public class EntityManager extends ResourceManager {
     static final public String NAME = "entity";
@@ -44,10 +45,12 @@ public EntityManager(DatabaseClient client) {
 
     /**
      * Retrieves a list of entities from the Server
-     * 
+     *
      * @return a list of entities
      */
     public List<Entity> getEntities() {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
+
         RequestParameters params = new RequestParameters();
         ServiceResultIterator resultItr = this.getServices().get(params);
         if (resultItr == null || ! resultItr.hasNext()) {
@@ -70,12 +73,15 @@ public List<Entity> getEntities() {
                 entities.add(entityFromXml((Element) children.item(i)));
             }
         }
+
+        PerformanceLogger.logTimeInsideMethod(startTime, "EntityManager.getEntities");
+
         return entities;
     }
 
     /**
      * Retrieve a named entity
-     * 
+     *
      * @param entityName
      *            - the name of the entity to retrieve
      * @return a entity

marklogic-data-hub/src/main/java/com/marklogic/hub/FlowManager.java

@@ -55,6 +55,7 @@
 import com.marklogic.hub.flow.Flow;
 import com.marklogic.hub.flow.FlowType;
 import com.marklogic.hub.flow.SimpleFlow;
+import com.marklogic.hub.util.PerformanceLogger;
 import com.marklogic.spring.batch.hub.CollectorReader;
 import com.marklogic.spring.batch.hub.FlowWriter;
 
@@ -153,7 +154,10 @@ public List<Flow> getFlows(String entityName) {
      * @return the flow
      */
     public Flow getFlow(String entityName, String flowName) {
-        return getFlow(entityName, flowName, null);
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
+        Flow flow = getFlow(entityName, flowName, null);
+        PerformanceLogger.logTimeInsideMethod(startTime, "FlowManager.getFlow");
+        return flow;
     }
 
     public Flow getFlow(String entityName, String flowName, FlowType flowType) {
@@ -196,6 +200,8 @@ public JobExecution runFlow(Flow flow, int batchSize) {
      * @return a JobExecution instance
      */
     public JobExecution runFlow(Flow flow, int batchSize, JobExecutionListener listener) {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
+
         Collector c = flow.getCollector();
         if (c instanceof ServerCollector) {
             ((ServerCollector)c).setClient(client);
@@ -217,9 +223,10 @@ public JobExecution runFlow(Flow flow, int batchSize, JobExecutionListener liste
 
         try {
             return jobLauncher.run(job, new JobParameters());
-        }
-        catch (Exception e) {
+        } catch (Exception e) {
             throw new RuntimeException(e);
+        } finally {
+            PerformanceLogger.logTimeInsideMethod(startTime, "FlowManager.runFlow");
         }
     }
 

marklogic-data-hub/src/main/java/com/marklogic/hub/Scaffolding.java

@@ -33,6 +33,7 @@
 import com.marklogic.client.io.Format;
 import com.marklogic.hub.flow.FlowType;
 import com.marklogic.hub.flow.SimpleFlow;
+import com.marklogic.hub.util.PerformanceLogger;
 
 public class Scaffolding {
 
@@ -51,20 +52,25 @@ public Scaffolding(String projectDir) {
     }
 
     public Path getFlowDir(String entityName, String flowName, FlowType flowType) {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         Path entityDir = entitiesDir.resolve(entityName);
         Path typeDir = entityDir.resolve(flowType.toString());
         Path flowDir = typeDir.resolve(flowName);
+        PerformanceLogger.logTimeInsideMethod(startTime, "Scaffolding.getFlowDir");
         return flowDir;
     }
 
     public void createEntity(String entityName) {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         Path entityDir = entitiesDir.resolve(entityName);
         entityDir.toFile().mkdirs();
+        PerformanceLogger.logTimeInsideMethod(startTime, "Scaffolding.createEntity");
     }
 
     public void createFlow(String entityName, String flowName,
             FlowType flowType, PluginFormat pluginFormat, Format dataFormat)
             throws IOException {
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         Path flowDir = getFlowDir(entityName, flowName, flowType);
 
         if (flowType.equals(FlowType.HARMONIZE)) {
@@ -101,6 +107,7 @@ public void createFlow(String entityName, String flowName,
             out.println(flow.serialize(false));
             out.close();
         }
+        PerformanceLogger.logTimeInsideMethod(startTime, "Scaffolding.createFlow");
     }
 
     private void writeFile(String srcFile, Path dstFile) throws IOException {
@@ -115,6 +122,8 @@ public void createRestExtension(String entityName, String extensionName,
             FlowType flowType, PluginFormat pluginFormat) throws IOException, ScaffoldingValidationException {
         LOGGER.info(extensionName);
 
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
+
         if(!validator.isUniqueRestServiceExtension(extensionName)) {
             throw new ScaffoldingValidationException("A rest service extension with the same name as " + extensionName + " already exists.");
         }
@@ -123,11 +132,13 @@ public void createRestExtension(String entityName, String extensionName,
         File dstFile = createEmptyRestExtensionFile(entityName, extensionName, flowType, pluginFormat);
         writeToFile(fileContent, dstFile);
         writeMetadataForFile(dstFile, scaffoldRestServicesPath + "metadata/template.xml", extensionName);
+        PerformanceLogger.logTimeInsideMethod(startTime, "Scaffolding.createRestExtension");
     }
 
     public void createRestTransform(String entityName, String transformName,
             FlowType flowType, PluginFormat pluginFormat) throws IOException, ScaffoldingValidationException {
         LOGGER.info(transformName);
+        long startTime = PerformanceLogger.monitorTimeInsideMethod();
         if(!validator.isUniqueRestTransform(transformName)) {
             throw new ScaffoldingValidationException("A rest transform with the same name as " + transformName + " already exists.");
         }
@@ -136,6 +147,7 @@ public void createRestTransform(String entityName, String transformName,
         File dstFile = createEmptyRestTransformFile(entityName, transformName, flowType, pluginFormat);
         writeToFile(fileContent, dstFile);
         writeMetadataForFile(dstFile, scaffoldRestTransformsPath + "metadata/template.xml", transformName);
+        PerformanceLogger.logTimeInsideMethod(startTime, "Scaffolding.createRestTransform");
     }
 
     private void writeToFile(String fileContent, File dstFile)

marklogic-data-hub/src/main/java/com/marklogic/hub/util/PerformanceLogger.java

@@ -0,0 +1,26 @@
+package com.marklogic.hub.util;
+
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class PerformanceLogger {
+
+    private final static Logger LOGGER = LoggerFactory.getLogger(PerformanceLogger.class);
+
+    public static long monitorTimeInsideMethod() {
+        return System.nanoTime();
+    }
+
+    public static void logTimeInsideMethod(long startTime, String location) {
+        long endTime = System.nanoTime();
+        long duration = (endTime - startTime) / 1000000000;
+
+        StringBuilder logMessage = new StringBuilder();
+        logMessage.append("PERFORMANCE: ");
+        logMessage.append(location);
+        logMessage.append(" took ");
+        logMessage.append(duration);
+        logMessage.append("s");
+        LOGGER.info(logMessage.toString());
+    }
+}