Added benchmark time logs

plugins/CuraEngineBackend/CuraEngineBackend.py

@@ -22,6 +22,7 @@ from . import StartSliceJob
 
 import os
 import sys
+from time import time
 
 from PyQt5.QtCore import QTimer
 
@@ -99,6 +100,8 @@ class CuraEngineBackend(Backend):
         Application.getInstance().getController().toolOperationStarted.connect(self._onToolOperationStarted)
         Application.getInstance().getController().toolOperationStopped.connect(self._onToolOperationStopped)
 
+        self._slice_start_time = None
+
     ##  Called when closing the application.
     #
     #   This function should terminate the engine process.
@@ -127,6 +130,7 @@ class CuraEngineBackend(Backend):
 
     ##  Perform a slice of the scene.
     def slice(self):
+        self._slice_start_time = time()
         if not self._enabled or not self._global_container_stack: #We shouldn't be slicing.
             # try again in a short time
             self._change_timer.start()
@@ -214,6 +218,7 @@ class CuraEngineBackend(Backend):
 
         # Preparation completed, send it to the backend.
         self._socket.sendMessage(job.getSliceMessage())
+        Logger.log("d", "Sending slice message took %s seconds", time() - self._slice_start_time )
 
     ##  Listener for when the scene has changed.
     #
@@ -277,7 +282,7 @@ class CuraEngineBackend(Backend):
         self.processingProgress.emit(1.0)
 
         self._slicing = False
-
+        Logger.log("d", "Slicing took %s seconds", time() - self._slice_start_time )
         if self._layer_view_active and (self._process_layers_job is None or not self._process_layers_job.isRunning()):
             self._process_layers_job = ProcessSlicedLayersJob.ProcessSlicedLayersJob(self._stored_layer_data)
             self._process_layers_job.start()

plugins/CuraEngineBackend/ProcessSlicedLayersJob.py

@@ -9,6 +9,7 @@ from UM.Mesh.MeshData import MeshData
 
 from UM.Message import Message
 from UM.i18n import i18nCatalog
+from UM.Logger import Logger
 
 from UM.Math.Vector import Vector
 
@@ -16,7 +17,7 @@ from cura import LayerDataBuilder
 from cura import LayerDataDecorator
 
 import numpy
-
+from time import time
 catalog = i18nCatalog("cura")
 
 
@@ -38,6 +39,7 @@ class ProcessSlicedLayersJob(Job):
         self._abort_requested = True
 
     def run(self):
+        start_time = time()
         if Application.getInstance().getController().getActiveView().getPluginId() == "LayerView":
             self._progress = Message(catalog.i18nc("@info:status", "Processing Layers"), 0, False, -1)
             self._progress.show()
@@ -147,6 +149,8 @@ class ProcessSlicedLayersJob(Job):
         # Clear the unparsed layers. This saves us a bunch of memory if the Job does not get destroyed.
         self._layers = None
 
+        Logger.log("d", "Processing layers took %s seconds", time() - start_time)
+
     def _onActiveViewChanged(self):
         if self.isRunning():
             if Application.getInstance().getController().getActiveView().getPluginId() == "LayerView":