455001: [Model Import] Log execution time information

https://bugs.eclipse.org/bugs/show_bug.cgi?id=455001

- Add more detailed log
- Log execution time for each individual transformation

2 files changed, 103 insertions, 10 deletions

diff --git a/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformation.java b/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformation.java
index e23e93e1a09..bf00217eb08 100644
--- a/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformation.java
+++ b/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformation.java
@@ -120,9 +120,15 @@ public class ImportTransformation {
 	/** Execution time, in nano-seconds */
 	protected long executionTime = 0L;
 
-	/** Execution time of the initial model loading */
+	/** Execution time of the initial model loading / ns */
 	protected long loadingTime = 0L;
 
+	/** Execution time for handling dangling references / ns */
+	protected long danglingRefTime = 0L;
+
+	/** Execution time for executing the UML-RT transformation / ns */
+	protected long importRTTime = 0L;
+
 	/** Source URI to Target URI map (For Models/Libraries/Fragments) */
 	protected final Map<URI, URI> uriMappings = new HashMap<URI, URI>();
 
@@ -239,6 +245,14 @@ public class ImportTransformation {
 		return loadingTime;
 	}
 
+	public long getHandleDanglingRefTime() {
+		return danglingRefTime;
+	}
+
+	public long getImportRTTime() {
+		return importRTTime;
+	}
+
 	public Map<URI, URI> getURIMappings() {
 		return uriMappings;
 	}
@@ -269,8 +283,6 @@ public class ImportTransformation {
 		} catch (Exception ex) {
 			Activator.log.error("An error occurred while loading " + getModelName(), ex);
 		}
-
-		monitor.subTask("Resolving all dependencies...");
 	}
 
 	/**
@@ -342,7 +354,7 @@ public class ImportTransformation {
 	// Preloads all required transformations (Either locally or statically, depending on the cache parameter)
 	protected IStatus loadTransformations(IProgressMonitor monitor) {
 		for (URI transformationURI : getAllTransformationURIs()) {
-			IStatus status = executorsPool.preLoad(transformationURI);
+			executorsPool.preLoad(transformationURI);
 			monitor.worked(1);
 		}
 
@@ -400,9 +412,10 @@ public class ImportTransformation {
 
 		IStatus result; // Result of an individual transformation (Will be aggregated to the complete GenerationStatus)
 
-		// UML RT (First operation, because it can transform Collaborations to Classes, which has some consequences on the diagram transformation)
-		// TODO: Restore the UML RT transformation (Update to UML RT v3)
+		long startRT = System.nanoTime();
 		result = importRTProfile(context, monitor);
+		long endRT = System.nanoTime();
+		this.importRTTime = endRT - startRT;
 		generationStatus.add(result);
 
 		// Diagrams
@@ -535,7 +548,10 @@ public class ImportTransformation {
 
 			monitor.subTask("Analyzing dangling references...");
 
+			long startDangling = System.nanoTime();
 			handleDanglingURIs(resourcesToSave);
+			long endDangling = System.nanoTime();
+			this.danglingRefTime = endDangling - startDangling;
 
 			monitor.subTask("Saving models...");
 
diff --git a/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformationLauncher.java b/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformationLauncher.java
index 6622c2c0535..6be59be28dc 100644
--- a/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformationLauncher.java
+++ b/extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformationLauncher.java
@@ -79,6 +79,9 @@ public class ImportTransformationLauncher {
 	// Nano to Second

 	protected final static long SECOND = 1000 * 1000 * 1000;

 

+	// Nano to Milliseconds

+	protected final static long MILLIS = 1000 * 1000;

+

 	protected final Config config;

 

 	protected final Control baseControl;

@@ -95,6 +98,16 @@ public class ImportTransformationLauncher {
 	protected long ownLoadingTime;

 

 	/**

+	 * Own cumulated execution time for repairing stereotypes

+	 */

+	protected long ownRepairStereotypesTime;

+

+	/**

+	 * Own cumulated execution time for repairing libraries

+	 */

+	protected long ownRepairLibrariesTime;

+

+	/**

 	 * The top-level job for this transformation

 	 */

 	protected Job importDependenciesJob;

@@ -143,21 +156,52 @@ public class ImportTransformationLauncher {
 			protected IStatus run(IProgressMonitor monitor) {

 				IStatus result = ImportTransformationLauncher.this.importModels(monitor, transformations);

 

-				long totalLoadingTime = 0L;

+				long cumulatedLoadingTime = 0L;

 				long cumulatedTransformationTime = 0L;

+				long cumulatedHandleDanglingTime = 0L;

+				long cumulatedImportRTTime = 0L;

 				for (ImportTransformation transformation : transformations) {

+					cumulatedLoadingTime += transformation.getLoadingTime();

+					cumulatedImportRTTime += transformation.getImportRTTime();

+					cumulatedHandleDanglingTime += transformation.getHandleDanglingRefTime();

+

 					cumulatedTransformationTime += transformation.getExecutionTime();

-					totalLoadingTime += transformation.getLoadingTime();

+

+					log("Import " + transformation.getModelName());

+					log("First phase (0-50%):");

+					log("\tTotal loading time: " + timeFormat(transformation.getLoadingTime()));

+					log("\tTotal Import UML-RT time: " + timeFormat(transformation.getImportRTTime()));

+					log("\tTotal Handle Dangling References time: " + timeFormat(transformation.getHandleDanglingRefTime()));

+					log("\tTotal execution time: " + timeFormat(transformation.getExecutionTime()));

+

+					Long loadingTime = loadingTimeV2.get(transformation);

+					Long repairProxiesTime = proxiesTime.get(transformation);

+					Long repairStereoTime = stereoTime.get(transformation);

+					Long totalPhase2 = totalTimeV2.get(transformation);

+

+					log("Second phase (50-100%):");

+					log("\tTotal loading time: " + timeFormat(loadingTime));

+					log("\tTotal fix proxies time: " + timeFormat(repairProxiesTime));

+					log("\tTotal fix stereotypes time: " + timeFormat(repairStereoTime));

+					log("\tTotal execution time: " + timeFormat(totalPhase2));

+

+					log("Total");

+					log("\tTotal execution time: " + timeFormat(transformation.getExecutionTime() + totalPhase2));

+					log("\n");

 				}

 

 				int nbThreads = Math.max(1, config.getMaxThreads());

 				log("First phase (0-50%) / " + nbThreads + " Threads");

 				log("\tCumulated Transformation Time: " + timeFormat(cumulatedTransformationTime));

-				log("\tCumulated Loading Time: " + timeFormat(totalLoadingTime));

+				log("\tCumulated Loading Time: " + timeFormat(cumulatedLoadingTime));

+				log("\tCumulated Handle Dangling Refs Time: " + timeFormat(cumulatedHandleDanglingTime));

+				log("\tCumulated Import RT Time: " + timeFormat(cumulatedImportRTTime));

 				log("\tTotal Transformation Time: " + timeFormat(transformationsExecutionTime));

 

 				log("Second phase (50-100%) / " + nbThreads + " Threads");

 				log("\tCumulated Loading Time: " + timeFormat(ownLoadingTime));

+				log("\tCumulated Fix Libraries Time: " + timeFormat(ownRepairLibrariesTime));

+				log("\tCumulated Fix Stereotypes Time: " + timeFormat(ownRepairStereotypesTime));

 				log("\tTotal Fix Dependencies Time: " + timeFormat(ownExecutionTime));

 

 				log("Total");

@@ -271,8 +315,15 @@ public class ImportTransformationLauncher {
 		return rsaConsole;

 	}

 

-	protected String timeFormat(long nano) {

+	protected String timeFormat(Long nano) {

+		if (nano == null) {

+			return "?"; // FIXME: crash?

+		}

 		long seconds = nano / SECOND;

+		if (seconds < 1) {

+			long millis = nano / MILLIS;

+			return String.format("%s ms", millis);

+		}

 		return String.format("%d:%02d:%02d", seconds / 3600, (seconds % 3600) / 60, (seconds % 60));

 	}

 

@@ -358,7 +409,12 @@ public class ImportTransformationLauncher {
 			Job transformationJob = new Job("Importing dependencies for " + transformation.getModelName()) {

 				@Override

 				protected IStatus run(IProgressMonitor monitor) {

+					long startFix = System.nanoTime();

 					fixDependencies(transformation, monitor, urisToReplace, profileUrisToReplace);

+					long endFix = System.nanoTime();

+					synchronized (ImportTransformationLauncher.this) {

+						totalTimeV2.put(transformation, endFix - startFix);

+					}

 

 					return Status.OK_STATUS;

 				}

@@ -375,6 +431,14 @@ public class ImportTransformationLauncher {
 		ownExecutionTime = end - begin - timeToIgnore;

 	}

 

+	final protected Map<ImportTransformation, Long> loadingTimeV2 = new HashMap<ImportTransformation, Long>();

+

+	final protected Map<ImportTransformation, Long> proxiesTime = new HashMap<ImportTransformation, Long>();

+

+	final protected Map<ImportTransformation, Long> stereoTime = new HashMap<ImportTransformation, Long>();

+

+	final protected Map<ImportTransformation, Long> totalTimeV2 = new HashMap<ImportTransformation, Long>();

+

 	protected IStatus fixDependencies(ImportTransformation transformation, IProgressMonitor monitor, Map<URI, URI> urisToReplace, Map<URI, URI> profileUrisToReplace) {

 		monitor.subTask("Importing dependencies for " + transformation.getModelName());

 		final ModelSet modelSet = new DiResourceSet();

@@ -394,6 +458,7 @@ public class ImportTransformationLauncher {
 			long endLoading = System.nanoTime();

 			synchronized (ImportTransformationLauncher.this) {

 				ownLoadingTime += endLoading - startLoading;

+				loadingTimeV2.put(transformation, endLoading - startLoading);

 			}

 		} catch (ModelMultiException e) {

 			Activator.log.error(e);

@@ -402,7 +467,13 @@ public class ImportTransformationLauncher {
 		}

 

 		try {

+			long startProxies = System.nanoTime();

 			repairProxies(modelSet, resourcesToRepair, urisToReplace, monitor); // Repairing proxies first will change the Applied Profiles. This helps repairing stereotypes

+			long endProxies = System.nanoTime();

+			synchronized (ImportTransformationLauncher.this) {

+				ownRepairLibrariesTime += endProxies - startProxies;

+				proxiesTime.put(transformation, endProxies - startProxies);

+			}

 		} catch (Exception ex) {

 			Activator.log.error(ex);

 			return new Status(IStatus.ERROR, Activator.PLUGIN_ID, "An exception occurred when repairing library dependencies", ex);

@@ -410,7 +481,13 @@ public class ImportTransformationLauncher {
 

 		RepairStereotypes repairStereotypesAction = new RepairStereotypes(modelSet, resourcesToRepair, profileUrisToReplace);

 		try {

+			long startStereotypes = System.nanoTime();

 			repairStereotypesAction.execute();

+			long endStereotypes = System.nanoTime();

+			synchronized (ImportTransformationLauncher.this) {

+				ownRepairStereotypesTime += endStereotypes - startStereotypes;

+				stereoTime.put(transformation, endStereotypes - startStereotypes);

+			}

 		} catch (Exception ex) {

 			Activator.log.error(ex);

 			return new Status(IStatus.ERROR, Activator.PLUGIN_ID, "An exception occurred when repairing profiles/stereotypes", ex);