From 3556d7c62f327845e0c3e4f33ebd918b468a0408 Mon Sep 17 00:00:00 2001 From: harlekin <5800926-mw102@users.noreply.gitlab.com> Date: Thu, 29 Sep 2022 14:06:40 +0000 Subject: [PATCH] Feat/timing --- src/main/java/com/sheepit/client/Client.java | 4 +- src/main/java/com/sheepit/client/Job.java | 80 ++++++++++++++++++- .../com/sheepit/client/RenderProcess.java | 12 +++ .../standalone/swing/activity/Working.java | 6 +- 4 files changed, 97 insertions(+), 5 deletions(-) diff --git a/src/main/java/com/sheepit/client/Client.java b/src/main/java/com/sheepit/client/Client.java index 0b13dda..8a667a0 100644 --- a/src/main/java/com/sheepit/client/Client.java +++ b/src/main/java/com/sheepit/client/Client.java @@ -683,7 +683,7 @@ import okhttp3.HttpUrl; if (job_to_reset_ != null) { remoteURL.addQueryParameter("frame", job_to_reset_.getFrameNumber()); remoteURL.addQueryParameter("job", job_to_reset_.getId()); - remoteURL.addQueryParameter("render_time", Integer.toString(job_to_reset_.getProcessRender().getDuration())); + remoteURL.addQueryParameter("render_time", Integer.toString(job_to_reset_.getProcessRender().getRenderDuration())); remoteURL.addQueryParameter("memoryused", Long.toString(job_to_reset_.getProcessRender().getPeakMemoryUsed())); } this.server.HTTPSendFile(remoteURL.build().toString(), temp_file.getAbsolutePath(), step_, this.gui); @@ -1062,7 +1062,7 @@ import okhttp3.HttpUrl; } protected Error.Type confirmJob(Job ajob, int checkpoint) { - String url_real = String.format(LOCALE, "%s&rendertime=%d&memoryused=%s", ajob.getValidationUrl(), ajob.getProcessRender().getDuration(), + String url_real = String.format(LOCALE, "%s&rendertime=%d&memoryused=%s", ajob.getValidationUrl(), ajob.getProcessRender().getRenderDuration(), ajob.getProcessRender().getPeakMemoryUsed()); this.log.debug(checkpoint, "Client::confirmeJob url " + url_real); this.log.debug(checkpoint, "path frame " + ajob.getOutputImagePath()); diff --git a/src/main/java/com/sheepit/client/Job.java b/src/main/java/com/sheepit/client/Job.java index cf6ba2b..8f7a4d7 100644 --- a/src/main/java/com/sheepit/client/Job.java +++ b/src/main/java/com/sheepit/client/Job.java @@ -24,6 +24,7 @@ import com.sheepit.client.Error.Type; import com.sheepit.client.os.OS; import lombok.Data; import lombok.Getter; +import org.simpleframework.xml.util.Match; import java.io.BufferedReader; import java.io.File; @@ -36,6 +37,8 @@ import java.io.StringWriter; import java.text.DateFormat; import java.text.ParseException; import java.text.SimpleDateFormat; +import java.time.Duration; +import java.time.Instant; import java.util.ArrayList; import java.util.Date; import java.util.HashMap; @@ -309,11 +312,19 @@ import java.util.regex.Pattern; }, configuration.getMaxRenderTime() * 1000 + 2000); // +2s to be sure the delay is over } + log.debug("renderer output"); try { int progress = -1; Pattern progressPattern = Pattern.compile(" (Rendered|Path Tracing Tile|Rendering|Sample) (\\d+)\\s?\\/\\s?(\\d+)( Tiles| samples|,)*"); + Pattern beginScenePrepPattern = Pattern.compile("Read blend:"); + Pattern beginPostProcessingPattern = Pattern.compile("^Fra:\\d* \\w*(.)* \\| (Compositing|Denoising)"); + Instant timeStamp = null; + Duration phaseDuration; //We divide the job into 3 phases: preparation, rendering, compositing + boolean scenePrepStarted = false; + boolean renderingStarted = false; + boolean postProcessingStarted = false; // Initialise the progress bar in the icon and the UI (0% completed at this time) gui.updateTrayIcon(0); @@ -333,12 +344,46 @@ import java.util.regex.Pattern; } } + Matcher scenePrepDetector = beginScenePrepPattern.matcher(line); + if (scenePrepStarted == false && scenePrepDetector.find()) { + scenePrepStarted = true; + timeStamp = Instant.now(); + } + progress = computeRenderingProgress(line, progressPattern, progress); + if (renderingStarted == false && progress != -1) { + renderingStarted = true; + if (timeStamp == null) { + timeStamp = new Date(process.getStartTime()).toInstant(); + } + phaseDuration = Duration.between(timeStamp, Instant.now()); + timeStamp = Instant.now(); + process.setScenePrepDuration((int) phaseDuration.toSeconds()); + } + + Matcher postProcessingDetector = beginPostProcessingPattern.matcher(line); + if (postProcessingStarted == false && postProcessingDetector.find()) { + postProcessingStarted = true; + if (timeStamp == null) { + timeStamp = new Date(process.getStartTime()).toInstant(); + } + phaseDuration = Duration.between(timeStamp, Instant.now()); + timeStamp = Instant.now(); + process.setRenderDuration((int) phaseDuration.toSeconds()); + } + if (configuration.getMaxAllowedMemory() != -1 && getProcessRender().getMemoryUsed().get() > configuration.getMaxAllowedMemory()) { log.debug("Blocking render because process ram used (" + getProcessRender().getMemoryUsed().get() + "k) is over user setting (" + configuration .getMaxAllowedMemory() + "k)"); OS.getOS().kill(process.getProcess()); process.finish(); + if (process.getRenderDuration() == -1) { + if (timeStamp == null) { + timeStamp = new Date(process.getStartTime()).toInstant(); + } + phaseDuration = Duration.between(timeStamp, Instant.now()); + process.setRenderDuration((int) phaseDuration.toSeconds()); + } if (script_file != null) { script_file.delete(); } @@ -357,6 +402,14 @@ import java.util.regex.Pattern; script_file.delete(); } + if (process.getRenderDuration() == -1) { + if (timeStamp == null) { + timeStamp = new Date(process.getStartTime()).toInstant(); + } + phaseDuration = Duration.between(timeStamp, Instant.now()); + process.setRenderDuration((int) phaseDuration.toSeconds()); + } + // Put back base icon gui.updateTrayIcon(Job.SHOW_BASE_ICON); @@ -367,7 +420,27 @@ import java.util.regex.Pattern; event.doNotifyIsStarted(); } } + + if (timeStamp == null) { + timeStamp = new Date(process.getStartTime()).toInstant(); + } + if (postProcessingStarted == false) { + phaseDuration = Duration.between(timeStamp, Instant.now()); + process.setRenderDuration((int) phaseDuration.toSeconds()); + } + else { + phaseDuration = Duration.between(timeStamp, Instant.now()); + process.setPostProcessingDuration((int) phaseDuration.toSeconds()); + } input.close(); + + log.debug(String.format("render times: %n\tScene prep: %ds%n\tRendering: %ss%n\tPost: %ss%n\tTotal: %ds%n\tRendering/Total: %.03f%n", + process.getScenePrepDuration(), + process.getRenderDuration(), + process.getPostProcessingDuration(), + process.getDuration(), + (Math.max(process.getRenderDuration(), 0) * 100.0) / process.getDuration() + )); } catch (IOException err1) { // for the input.readline // most likely The handle is invalid @@ -470,7 +543,12 @@ import java.util.regex.Pattern; scene_dir.delete(); } - gui.status(String.format("Frame rendered in %dmin%ds", process.getDuration() / 60, process.getDuration() % 60)); + gui.status(String.format("Frame finished in %dmin%ds, render time: %dmin%ds", + process.getDuration() / 60, + process.getDuration() % 60, + process.getRenderDuration() / 60, + process.getRenderDuration() % 60) + ); return Error.Type.OK; } diff --git a/src/main/java/com/sheepit/client/RenderProcess.java b/src/main/java/com/sheepit/client/RenderProcess.java index 4ea7887..9de57a2 100644 --- a/src/main/java/com/sheepit/client/RenderProcess.java +++ b/src/main/java/com/sheepit/client/RenderProcess.java @@ -23,11 +23,20 @@ import lombok.Data; import java.util.Date; import java.util.concurrent.atomic.AtomicLong; + +import lombok.Setter; import oshi.software.os.OSProcess; @Data public class RenderProcess { private long startTime; private long endTime; + + @Setter + private int scenePrepDuration; + @Setter + private int renderDuration; + @Setter + private int postProcessingDuration; private int remainingDuration; // in seconds private AtomicLong memoryUsed; // in kB private long peakMemoryUsed; // in kB @@ -41,6 +50,9 @@ import oshi.software.os.OSProcess; osProcess = null; startTime = -1; endTime = -1; + scenePrepDuration = -1; + renderDuration = -1; + postProcessingDuration = -1; memoryUsed = new AtomicLong(0); peakMemoryUsed = 0; coresUsed = 0; diff --git a/src/main/java/com/sheepit/client/standalone/swing/activity/Working.java b/src/main/java/com/sheepit/client/standalone/swing/activity/Working.java index 0f7524b..bf1e723 100644 --- a/src/main/java/com/sheepit/client/standalone/swing/activity/Working.java +++ b/src/main/java/com/sheepit/client/standalone/swing/activity/Working.java @@ -418,8 +418,10 @@ public class Working implements Activity { lastRender.setIcon(icon); // don't use lastJob.getProcessRender().getDuration() due to timezone if (lastJob.getProcessRender().getDuration() > 1) { - lastRenderTime.setText("Render time : " + Utils - .humanDuration(new Date(lastJob.getProcessRender().getEndTime() - lastJob.getProcessRender().getStartTime()))); + lastRenderTime.setText( + "Total time : " + Utils.humanDuration(new Date(lastJob.getProcessRender().getEndTime() - lastJob.getProcessRender().getStartTime())) + + "; Render time : " + Utils.humanDuration(new Date(lastJob.getProcessRender().getRenderDuration() * 1000L)) + ); } } }