Skip to main content
aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorCamille Letavernier2015-01-21 09:19:34 -0500
committerCamille Letavernier2015-01-21 09:19:34 -0500
commitbda6a528152650d9f35d5756314b3b31941a4521 (patch)
tree30eafa7875377eedc349173dca6671f32dd70d14
parentc81705910eef178ff6660b340cd843fb5f212d80 (diff)
downloadorg.eclipse.papyrus-bda6a528152650d9f35d5756314b3b31941a4521.tar.gz
org.eclipse.papyrus-bda6a528152650d9f35d5756314b3b31941a4521.tar.xz
org.eclipse.papyrus-bda6a528152650d9f35d5756314b3b31941a4521.zip
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
-rw-r--r--extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformation.java28
-rw-r--r--extraplugins/migration/org.eclipse.papyrus.migration.rsa/src/org/eclipse/papyrus/migration/rsa/transformation/ImportTransformationLauncher.java85
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);

Back to the top