diff --git a/src/octoprint/events.py b/src/octoprint/events.py index 23e673d2..d69b39ae 100644 --- a/src/octoprint/events.py +++ b/src/octoprint/events.py @@ -42,6 +42,7 @@ class Events(object): UPDATED_FILES = "UpdatedFiles" METADATA_ANALYSIS_STARTED = "MetadataAnalysisStarted" METADATA_ANALYSIS_FINISHED = "MetadataAnalysisFinished" + METADATA_STATISTICS_UPDATED = "MetadataStatisticsUpdated" # SD Upload TRANSFER_STARTED = "TransferStarted" diff --git a/src/octoprint/filemanager/__init__.py b/src/octoprint/filemanager/__init__.py index 55e6b1be..9c65a67a 100644 --- a/src/octoprint/filemanager/__init__.py +++ b/src/octoprint/filemanager/__init__.py @@ -159,7 +159,7 @@ class FileManager(object): position=None, profile=None, printer_profile_id=None, overrides=None, callback=None, callback_args=None): absolute_source_path = self.get_absolute_path(source_location, source_path) - def stlProcessed(source_location, source_path, tmp_path, dest_location, dest_path, start_time, printer_profile_id, callback, callback_args, _error=None, _cancelled=False): + def stlProcessed(source_location, source_path, tmp_path, dest_location, dest_path, start_time, printer_profile_id, callback, callback_args, _error=None, _cancelled=False, _analysis=None): try: if _error: eventManager().fire(Events.SLICING_FAILED, {"stl": source_path, "gcode": dest_path, "reason": _error}) @@ -187,7 +187,7 @@ class FileManager(object): file_obj = Wrapper(stl_name, temp_path, hash) printer_profile = self._printer_profile_manager.get(printer_profile_id) - self.add_file(dest_location, dest_path, file_obj, links=links, allow_overwrite=True, printer_profile=printer_profile) + self.add_file(dest_location, dest_path, file_obj, links=links, allow_overwrite=True, printer_profile=printer_profile, analysis=_analysis) end_time = time.time() eventManager().fire(Events.SLICING_DONE, {"stl": source_path, "gcode": dest_path, "time": end_time - start_time}) @@ -286,17 +286,20 @@ class FileManager(object): result[dst] = self._storage_managers[dst].list_files(path=path, filter=filter, recursive=recursive) return result - def add_file(self, destination, path, file_object, links=None, allow_overwrite=False, printer_profile=None): + def add_file(self, destination, path, file_object, links=None, allow_overwrite=False, printer_profile=None, analysis=None): if printer_profile is None: printer_profile = self._printer_profile_manager.get_current_or_default() file_path = self._storage(destination).add_file(path, file_object, links=links, printer_profile=printer_profile, allow_overwrite=allow_overwrite) absolute_path = self._storage(destination).get_absolute_path(file_path) - file_type = get_file_type(absolute_path) - if file_type: - queue_entry = QueueEntry(file_path, file_type[-1], destination, absolute_path, printer_profile) - self._analysis_queue.enqueue(queue_entry, high_priority=True) + if analysis is None: + file_type = get_file_type(absolute_path) + if file_type: + queue_entry = QueueEntry(file_path, file_type[-1], destination, absolute_path, printer_profile) + self._analysis_queue.enqueue(queue_entry, high_priority=True) + else: + self._add_analysis_result(destination, path, analysis) eventManager().fire(Events.UPDATED_FILES, dict(type="printables")) return file_path @@ -323,9 +326,13 @@ class FileManager(object): def remove_link(self, destination, path, rel, data): self._storage(destination).remove_link(path, rel, data) - def log_print(self, destination, path, timestamp, print_time, success): + def log_print(self, destination, path, timestamp, print_time, success, printer_profile): try: - self._storage(destination).add_history(path, dict(timestamp=timestamp, printTime=print_time, success=success)) + if success: + self._storage(destination).add_history(path, dict(timestamp=timestamp, printTime=print_time, success=success, printerProfile=printer_profile)) + else: + self._storage(destination).add_history(path, dict(timestamp=timestamp, success=success, printerProfile=printer_profile)) + eventManager().fire(Events.METADATA_STATISTICS_UPDATED, dict(storage=destination, path=path)) except NoSuchStorage: # if there's no storage configured where to log the print, we'll just not log it pass @@ -362,10 +369,13 @@ class FileManager(object): raise NoSuchStorage("No storage configured for destination {destination}".format(**locals())) return self._storage_managers[destination] - def _on_analysis_finished(self, entry, result): - if not entry.location in self._storage_managers: + def _add_analysis_result(self, destination, path, result): + if not destination in self._storage_managers: return - storage_manager = self._storage_managers[entry.location] - storage_manager.set_additional_metadata(entry.path, "analysis", result) + storage_manager = self._storage_managers[destination] + storage_manager.set_additional_metadata(path, "analysis", result) + + def _on_analysis_finished(self, entry, result): + self._add_analysis_result(entry.location, entry.path, result) diff --git a/src/octoprint/filemanager/storage.py b/src/octoprint/filemanager/storage.py index 010b738c..54d13a43 100644 --- a/src/octoprint/filemanager/storage.py +++ b/src/octoprint/filemanager/storage.py @@ -501,6 +501,7 @@ class LocalFileStorage(StorageInterface): metadata[name]["history"] = [] metadata[name]["history"].append(data) + self._calculate_stats_from_history(name, path, metadata=metadata, save=False) self._save_metadata(path, metadata) def _update_history(self, name, path, index, data): @@ -510,7 +511,8 @@ class LocalFileStorage(StorageInterface): return try: - metadata[name]["history"][index] = data + metadata[name]["history"][index].update(data) + self._calculate_stats_from_history(name, path, metadata=metadata, save=False) self._save_metadata(path, metadata) except IndexError: pass @@ -523,10 +525,55 @@ class LocalFileStorage(StorageInterface): try: del metadata[name]["history"][index] + self._calculate_stats_from_history(name, path, metadata=metadata, save=False) self._save_metadata(path, metadata) except IndexError: pass + def _calculate_stats_from_history(self, name, path, metadata=None, save=True): + if metadata is None: + metadata = self._get_metadata(path) + + if not name in metadata or not "history" in metadata[name]: + return + + # collect data from history + former_print_times = dict() + last_print = dict() + + + for history_entry in metadata[name]["history"]: + if not "printTime" in history_entry or not "success" in history_entry or not history_entry["success"] or not "printerProfile" in history_entry: + continue + + printer_profile = history_entry["printerProfile"] + print_time = history_entry["printTime"] + + if not printer_profile in former_print_times: + former_print_times[printer_profile] = [] + former_print_times[printer_profile].append(print_time) + + if not printer_profile in last_print or last_print[printer_profile] is None or ("timestamp" in history_entry and history_entry["timestamp"] > last_print[printer_profile]["timestamp"]): + last_print[printer_profile] = history_entry + + # calculate stats + statistics = dict(averagePrintTime=dict(), lastPrintTime=dict()) + + for printer_profile in former_print_times: + if not former_print_times[printer_profile]: + continue + statistics["averagePrintTime"][printer_profile] = sum(former_print_times[printer_profile]) / float(len(former_print_times[printer_profile])) + + for printer_profile in last_print: + if not last_print[printer_profile]: + continue + statistics["lastPrintTime"][printer_profile] = last_print[printer_profile]["printTime"] + + metadata[name]["statistics"] = statistics + + if save: + self._save_metadata(path, metadata) + def _get_links(self, name, path, searched_rel): metadata = self._get_metadata(path) result = [] diff --git a/src/octoprint/plugins/cura/__init__.py b/src/octoprint/plugins/cura/__init__.py index d4c06f7c..4e9653e3 100644 --- a/src/octoprint/plugins/cura/__init__.py +++ b/src/octoprint/plugins/cura/__init__.py @@ -9,6 +9,7 @@ import logging import logging.handlers import os import flask +import math import octoprint.plugin import octoprint.util @@ -278,6 +279,7 @@ class CuraPlugin(octoprint.plugin.SlicerPlugin, skin=1, export=2 ) + analysis = None while p.returncode is None: line = p.stderr.readline(timeout=0.5) if not line: @@ -331,6 +333,39 @@ class CuraPlugin(octoprint.plugin.SlicerPlugin, continue on_progress_kwargs["_progress"] = (step_factor[step] * layer_count + current_layer) / (layer_count * 3) on_progress(*on_progress_args, **on_progress_kwargs) + + elif line.startswith("Print time:"): + try: + print_time = int(line[len("Print time:"):].strip()) + if analysis is None: + analysis = dict() + analysis["estimatedPrintTime"] = print_time + except: + pass + + elif line.startswith("Filament:") or line.startswith("Filament2:"): + if line.startswith("Filament:"): + filament_str = line[len("Filament:"):].strip() + tool_key = "tool0" + else: + filament_str = line[len("Filament2:"):].strip() + tool_key = "tool1" + + try: + filament = int(filament_str) + if analysis is None: + analysis = dict() + if not "filament" in analysis: + analysis["filament"] = dict() + if not tool_key in analysis["filament"]: + analysis["filament"][tool_key] = dict() + analysis["filament"][tool_key]["length"] = filament + if "filamentDiameter" in engine_settings: + radius_in_cm = float(int(engine_settings["filamentDiameter"]) / 10000.0) / 2.0 + filament_in_cm = filament / 10.0 + analysis["filament"][tool_key]["volume"] = filament_in_cm * math.pi * radius_in_cm * radius_in_cm + except: + pass finally: p.close() @@ -341,7 +376,7 @@ class CuraPlugin(octoprint.plugin.SlicerPlugin, self._cura_logger.info("### Finished, returncode %d" % p.returncode) if p.returncode == 0: - return True, None + return True, dict(analysis=analysis) else: self._logger.warn("Could not slice via Cura, got return code %r" % p.returncode) return False, "Got returncode %r" % p.returncode diff --git a/src/octoprint/printer/__init__.py b/src/octoprint/printer/__init__.py index 8b1c25cf..a61a2cda 100644 --- a/src/octoprint/printer/__init__.py +++ b/src/octoprint/printer/__init__.py @@ -36,6 +36,7 @@ class Printer(): self._logger = logging.getLogger(__name__) self._estimationLogger = logging.getLogger("ESTIMATIONS") + self._printTimeLogger = logging.getLogger("PRINT_TIME") self._analysisQueue = analysisQueue self._fileManager = fileManager @@ -114,7 +115,8 @@ class Printer(): currentZ=None ) - eventManager().subscribe(Events.METADATA_ANALYSIS_FINISHED, self.onMetadataAnalysisFinished); + eventManager().subscribe(Events.METADATA_ANALYSIS_FINISHED, self.onMetadataAnalysisFinished) + eventManager().subscribe(Events.METADATA_STATISTICS_UPDATED, self.onMetadataStatisticsUpdated) #~~ callback handling @@ -164,6 +166,11 @@ class Printer(): self._selectedFile["filesize"], self._selectedFile["sd"]) + def onMetadataStatisticsUpdated(self, event, data): + self._setJobData(self._selectedFile["filename"], + self._selectedFile["filesize"], + self._selectedFile["sd"]) + #~~ progress plugin reporting def _reportPrintProgressToPlugins(self, progress): @@ -348,7 +355,7 @@ class Printer(): # mark print as failure if self._selectedFile is not None: - self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False) + self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False, self._printerProfileManager.get_current_or_default()["id"]) payload = { "file": self._selectedFile["filename"], "origin": FileDestinations.LOCAL @@ -398,10 +405,26 @@ class Printer(): def _setProgressData(self, progress, filepos, printTime, cleanedPrintTime): estimatedTotalPrintTime = self._estimateTotalPrintTime(progress, cleanedPrintTime) + statisticalTotalPrintTime = None + totalPrintTime = estimatedTotalPrintTime + + if self._selectedFile and "estimatedPrintTime" in self._selectedFile and self._selectedFile["estimatedPrintTime"]: + statisticalTotalPrintTime = self._selectedFile["estimatedPrintTime"] + if progress and cleanedPrintTime: + if estimatedTotalPrintTime is None: + totalPrintTime = statisticalTotalPrintTime + else: + if progress < 0.5: + sub_progress = progress * 2 + else: + sub_progress = 1.0 + totalPrintTime = (1 - sub_progress) * statisticalTotalPrintTime + sub_progress * estimatedTotalPrintTime + + #self._printTimeLogger.info("{progress};{cleanedPrintTime};{estimatedTotalPrintTime};{statisticalTotalPrintTime};{totalPrintTime}".format(**locals())) self._progress = progress self._printTime = printTime - self._printTimeLeft = estimatedTotalPrintTime - cleanedPrintTime if (estimatedTotalPrintTime is not None and cleanedPrintTime is not None) else None + self._printTimeLeft = totalPrintTime - cleanedPrintTime if (totalPrintTime is not None and cleanedPrintTime is not None) else None self._stateMonitor.setProgress({ "completion": self._progress * 100 if self._progress is not None else None, @@ -447,6 +470,7 @@ class Printer(): "filename": filename, "filesize": filesize, "sd": sd, + "estimatedPrintTime": None } else: self._selectedFile = None @@ -458,12 +482,15 @@ class Printer(): "date": None }, "estimatedPrintTime": None, + "averagePrintTime": None, + "lastPrintTime": None, "filament": None, }) return estimatedPrintTime = None lastPrintTime = None + averagePrintTime = None date = None filament = None if filename: @@ -482,8 +509,18 @@ class Printer(): estimatedPrintTime = fileData["analysis"]["estimatedPrintTime"] if "filament" in fileData["analysis"].keys(): filament = fileData["analysis"]["filament"] - if "prints" in fileData and fileData["prints"] and "last" in fileData["prints"] and fileData["prints"]["last"] and "lastPrintTime" in fileData["prints"]["last"]: - lastPrintTime = fileData["prints"]["last"]["lastPrintTime"] + if "statistics" in fileData: + printer_profile = self._printerProfileManager.get_current_or_default()["id"] + if "averagePrintTime" in fileData["statistics"] and printer_profile in fileData["statistics"]["averagePrintTime"]: + averagePrintTime = fileData["statistics"]["averagePrintTime"][printer_profile] + if "lastPrintTime" in fileData["statistics"] and printer_profile in fileData["statistics"]["lastPrintTime"]: + lastPrintTime = fileData["statistics"]["lastPrintTime"][printer_profile] + + if averagePrintTime is not None: + self._selectedFile["estimatedPrintTime"] = averagePrintTime + elif estimatedPrintTime is not None: + # TODO apply factor which first needs to be tracked! + self._selectedFile["estimatedPrintTime"] = estimatedPrintTime self._stateMonitor.setJobData({ "file": { @@ -493,6 +530,7 @@ class Printer(): "date": date }, "estimatedPrintTime": estimatedPrintTime, + "averagePrintTime": averagePrintTime, "lastPrintTime": lastPrintTime, "filament": filament, }) @@ -543,9 +581,9 @@ class Printer(): if self._comm is not None and oldState == self._comm.STATE_PRINTING: if self._selectedFile is not None: if state == self._comm.STATE_OPERATIONAL: - self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), True) + self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), True, self._printerProfileManager.get_current_or_default()["id"]) elif state == self._comm.STATE_CLOSED or state == self._comm.STATE_ERROR or state == self._comm.STATE_CLOSED_WITH_ERROR: - self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False) + self._fileManager.log_print(FileDestinations.SDCARD if self._selectedFile["sd"] else FileDestinations.LOCAL, self._selectedFile["filename"], time.time(), self._comm.getPrintTime(), False, self._printerProfileManager.get_current_or_default()["id"]) self._analysisQueue.resume() # printing done, put those cpu cycles to good use elif self._comm is not None and state == self._comm.STATE_PRINTING: self._analysisQueue.pause() # do not analyse files while printing diff --git a/src/octoprint/server/api/files.py b/src/octoprint/server/api/files.py index 840ba5e0..adcbb791 100644 --- a/src/octoprint/server/api/files.py +++ b/src/octoprint/server/api/files.py @@ -99,10 +99,11 @@ def _getFileList(origin, filter=None): failure=failure, last=dict( success=last["success"], - date=last["timestamp"], - printTime=last["printTime"] + date=last["timestamp"] ) ) + if "printTime" in last: + prints["last"]["printTime"] = last["printTime"] file["prints"] = prints file.update({ diff --git a/src/octoprint/slicing/__init__.py b/src/octoprint/slicing/__init__.py index afefae3e..af90d414 100644 --- a/src/octoprint/slicing/__init__.py +++ b/src/octoprint/slicing/__init__.py @@ -136,6 +136,8 @@ class SlicingManager(object): if not ok: callback_kwargs.update(dict(_error=result)) + elif result is not None and isinstance(result, dict) and "analysis" in result: + callback_kwargs.update(dict(_analysis=result["analysis"])) except SlicingCancelled: callback_kwargs.update(dict(_cancelled=True)) finally: diff --git a/src/octoprint/util/gcodeInterpreter.py b/src/octoprint/util/gcodeInterpreter.py index 1b4a1573..a7b9c500 100644 --- a/src/octoprint/util/gcodeInterpreter.py +++ b/src/octoprint/util/gcodeInterpreter.py @@ -87,8 +87,13 @@ class gcode(object): self._filamentDiameter = float(filamentValue.split(",")[0].strip()) except ValueError: self._filamentDiameter = 0.0 - elif comment.startswith("CURA_PROFILE_STRING"): - curaOptions = self._parseCuraProfileString(comment) + elif comment.startswith("CURA_PROFILE_STRING") or comment.startswith("CURA_OCTO_PROFILE_STRING"): + if comment.startswith("CURA_PROFILE_STRING"): + prefix = "CURA_PROFILE_STRING:" + else: + prefix = "CURA_OCTO_PROFILE_STRING:" + + curaOptions = self._parseCuraProfileString(comment, prefix) if "filament_diameter" in curaOptions: try: self._filamentDiameter = float(curaOptions["filament_diameter"]) @@ -239,8 +244,8 @@ class gcode(object): self.extrusionVolume[i] = (self.extrusionAmount[i] * (math.pi * radius * radius)) / 1000 self.totalMoveTimeMinute = totalMoveTimeMinute - def _parseCuraProfileString(self, comment): - return {key: value for (key, value) in map(lambda x: x.split("=", 1), zlib.decompress(base64.b64decode(comment[len("CURA_PROFILE_STRING:"):])).split("\b"))} + def _parseCuraProfileString(self, comment, prefix): + return {key: value for (key, value) in map(lambda x: x.split("=", 1), zlib.decompress(base64.b64decode(comment[len(prefix):])).split("\b"))} def getCodeInt(line, code): diff --git a/tests/printer/test_estimation.py b/tests/printer/test_estimation.py index 5096d9e8..ad43d11d 100644 --- a/tests/printer/test_estimation.py +++ b/tests/printer/test_estimation.py @@ -16,6 +16,7 @@ class EstimationTestCase(unittest.TestCase): def setUp(self): self.estimation_helper = type(octoprint.printer.TimeEstimationHelper)(octoprint.printer.TimeEstimationHelper.__name__, (octoprint.printer.TimeEstimationHelper,), { + 'STABLE_THRESHOLD': 0.1, 'STABLE_ROLLING_WINDOW': 3, 'STABLE_COUNTDOWN': 1 })()