Merge pull request #470 from jeanouii/feat/462/add-timings-jar-war

feat(#462) add timings jar war

org.eclipse.transformer/src/main/java/org/eclipse/transformer/action/Changes.java

@@ -24,6 +24,7 @@ public interface Changes {
  boolean isRenamed();
  boolean isContentChanged();
  String getChangeText();
+ long getElapsedMillis();
 
  void log(Logger logger, String inputPath, String outputPath);
 }

org.eclipse.transformer/src/main/java/org/eclipse/transformer/action/impl/ActionImpl.java

@@ -220,8 +220,8 @@ public void stopRecording(String inputName) {
  Changes useActiveChanges = activeChanges;
  Logger useLogger = getLogger();
  if (useLogger.isDebugEnabled()) {
- useLogger.debug("Stop processing [ {} ] using [ {} ]: {}", inputName, getName(),
- useActiveChanges.getChangeText());
+ useLogger.debug("Stop processing [ {} ] using [ {} ] took [ {}ms ]: {}", inputName, getName(),
+ useActiveChanges.getElapsedMillis(), useActiveChanges.getChangeText());
  }
  lastActiveChanges = useActiveChanges;
  activeChanges = changes.pollLast();

org.eclipse.transformer/src/main/java/org/eclipse/transformer/action/impl/ChangesImpl.java

@@ -16,8 +16,12 @@
 import org.eclipse.transformer.action.Changes;
 import org.slf4j.Logger;
 
+import java.util.concurrent.TimeUnit;
+
 public abstract class ChangesImpl implements Changes {
 
+ private final long start = System.nanoTime();
+
  public ChangesImpl() {
  // Empty
  }
@@ -101,15 +105,30 @@ public void log(Logger logger, String inputPath, String outputPath) {
  logger.info(consoleMarker, "Input [ {} ] as [ {} ]", getInputResourceName(), inputPath);
  }
  if (useOutputName.equals(outputPath)) {
- logger.info(consoleMarker, "Output [ {} ]", outputPath);
+ logger.info(consoleMarker, "Output [ {} ] took [ {} ]", outputPath,
+ toHoursMinutesSeconds(getElapsedMillis()));
  } else {
- logger.info(consoleMarker, "Output [ {} ] as [ {} ]", getOutputResourceName(), outputPath);
+ logger.info(consoleMarker, "Output [ {} ] as [ {} ] took [ {} ]", getOutputResourceName(), outputPath,
+ toHoursMinutesSeconds(getElapsedMillis()));
  }
 
  logChanges(logger);
  }
  }
 
+ public static String toHoursMinutesSeconds(final long millis) {
+ final long seconds = millis / 1000;
+ final long HH = seconds / 3600;
+ final long MM = (seconds % 3600) / 60;
+ final long SS = seconds % 60;
+ return String.format("%02d:%02d:%02d", HH, MM, SS);
+ }
+
+ @Override
+ public long getElapsedMillis() {
+ return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start);
+ }
+
  protected void logChanges(Logger logger) {
  logger.info(consoleMarker, "Changes [ {} ]", getChangeText());
  }

org.eclipse.transformer/src/main/java/org/eclipse/transformer/action/impl/ZipActionImpl.java

@@ -86,6 +86,10 @@ public void apply(String inputPath, File inputFile, String outputPath, File outp
  try {
  setResourceNames(inputPath, outputPath);
  applyFile(inputPath, inputFile, outputPath, outputFile);
+
+ // print the timings for the current archive and a tip for user if archive hasn't been updated
+ printZipActionDuration(inputPath);
+ printAdviseOnUnchanged(inputPath);
  } finally {
  stopRecording(inputPath);
  }
@@ -111,6 +115,12 @@ public ByteData apply(ByteData inputData) throws TransformException {
  ? outputStream.toByteBuffer()
  : inputData.buffer();
  ByteData outputData = new ByteDataImpl(outputPath, outputBuffer, inputData.charset());
+
+
+ // print the timings for the current archive and a tip for user if archive hasn't been updated
+ printZipActionDuration(inputPath);
+ printAdviseOnUnchanged(inputPath);
+
  return outputData;
  } finally {
  stopRecording(inputPath);
@@ -130,6 +140,11 @@ private void apply(String inputPath, InputStream inputStream, String outputPath,
  try {
  setResourceNames(inputPath, outputPath);
  applyStream(inputPath, inputStream, outputPath, outputStream);
+
+ // print the timings for the current archive and a tip for user if archive hasn't been updated
+ printZipActionDuration(inputPath);
+ printAdviseOnUnchanged(inputPath);
+
  } finally {
  stopRecording(inputPath);
  }
@@ -418,6 +433,25 @@ private void applyZipStream(
  }
  }
 
+ private void printZipActionDuration(final String inputName) {
+ if (getLogger().isInfoEnabled()) {
+ getLogger().info("Stop processing [ {} ] using [ {} ] took [ {}ms ]: {}",
+ inputName, getName(),
+ getActiveChanges().getElapsedMillis(), getActiveChanges().getChangeText());
+ }
+ }
+
+ private void printAdviseOnUnchanged(final String inputName) {
+ if (getLogger().isInfoEnabled() && !getActiveChanges().isChanged()) {
+ // we could at least test all ZipActionImpl, but if we do it
+ // accurately for archive actions (JAR, WAR, EAR, ...), it will dramatically speed up the conversion
+ // kinda compromise
+ getLogger().info("[ {} ] has been processed without changes. If you don't alter the rules, you can exclude " +
+ "it to speed up next iterations using [ {}=! ] in the selection configuration file.",
+ inputName, inputName);
+ }
+ }
+
  private void copy(
  ZipEntry inputEntry, ZipInputStream zipInputStream,
  String outputName, ZipOutputStream zipOutputStream,