From ea0436eef5093967832cbaec052a19c30cac132c Mon Sep 17 00:00:00 2001 From: Jelle Spijker Date: Tue, 31 Oct 2023 20:24:27 +0100 Subject: [PATCH 01/10] Update conanfile.py --- conanfile.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/conanfile.py b/conanfile.py index b498c3b84d..b3e464843a 100644 --- a/conanfile.py +++ b/conanfile.py @@ -40,7 +40,7 @@ class CuraEngineConan(ConanFile): def set_version(self): if not self.version: - self.version = "5.6.0-alpha" + self.version = "5.6.0-beta.1" def export_sources(self): copy(self, "CMakeLists.txt", self.recipe_folder, self.export_sources_folder) From 13a059ec1b33d7a920a3d41c477659b413511f92 Mon Sep 17 00:00:00 2001 From: Erwan MATHIEU Date: Thu, 2 Nov 2023 16:49:22 +0100 Subject: [PATCH 02/10] Detailed timing logging for layer export CURA-11255 --- include/FffGcodeWriter.h | 11 +++++-- include/LayerPlanBuffer.h | 9 +++--- include/progress/Progress.h | 46 ++++++++++++++------------ include/utils/gettime.h | 61 ++++++++++++++--------------------- src/FffGcodeWriter.cpp | 42 ++++++++++++++++-------- src/MeshGroup.cpp | 15 ++++++--- src/Scene.cpp | 13 +++++--- src/progress/Progress.cpp | 64 ++++++++++++++++++++++--------------- src/slicer.cpp | 18 +++++------ src/utils/gettime.cpp | 24 ++++++++++---- 10 files changed, 175 insertions(+), 128 deletions(-) diff --git a/include/FffGcodeWriter.h b/include/FffGcodeWriter.h index 7e5908e136..d63547692e 100644 --- a/include/FffGcodeWriter.h +++ b/include/FffGcodeWriter.h @@ -14,6 +14,7 @@ #include "settings/PathConfigStorage.h" //For the MeshPathConfigs subclass. #include "utils/ExtrusionLine.h" //Processing variable-width paths. #include "utils/NoCopy.h" +#include "utils/gettime.h" namespace cura { @@ -25,7 +26,6 @@ class SliceDataStorage; class SliceMeshStorage; class SliceLayer; class SliceLayerPart; -class TimeKeeper; /*! * Secondary stage in Fused Filament Fabrication processing: The generated polygons are used in the gcode generation. @@ -139,6 +139,13 @@ class FffGcodeWriter : public NoCopy void writeGCode(SliceDataStorage& storage, TimeKeeper& timeKeeper); private: + struct ProcessLayerResult + { + LayerPlan* layer_plan; + double total_elapsed_time; + TimeKeeper::RegisteredTimes stages_times; + }; + /*! * \brief Set the FffGcodeWriter::fan_speed_layer_time_settings by * retrieving all settings from the global/per-meshgroup settings. @@ -210,7 +217,7 @@ class FffGcodeWriter : public NoCopy * \param total_layers The total number of layers. * \return The layer plans */ - LayerPlan& processLayer(const SliceDataStorage& storage, LayerIndex layer_nr, const size_t total_layers) const; + ProcessLayerResult processLayer(const SliceDataStorage& storage, LayerIndex layer_nr, const size_t total_layers) const; /*! * This function checks whether prime blob should happen for any extruder on the first layer. diff --git a/include/LayerPlanBuffer.h b/include/LayerPlanBuffer.h index 8898137b87..2b1ce8cefc 100644 --- a/include/LayerPlanBuffer.h +++ b/include/LayerPlanBuffer.h @@ -4,6 +4,9 @@ #ifndef LAYER_PLAN_BUFFER_H #define LAYER_PLAN_BUFFER_H +#include +#include + #include "ExtruderPlan.h" #include "LayerPlan.h" #include "Preheat.h" @@ -11,9 +14,6 @@ #include "settings/Settings.h" #include "settings/types/Duration.h" -#include -#include - namespace cura { @@ -36,7 +36,6 @@ class GCodeExport; class LayerPlanBuffer { friend class LayerPlan; - friend class LayerPlanBuffer; GCodeExport& gcode; Preheat preheat_config; //!< the nozzle and material temperature settings for each extruder train. @@ -215,4 +214,4 @@ class LayerPlanBuffer } // namespace cura -#endif // LAYER_PLAN_BUFFER_H \ No newline at end of file +#endif // LAYER_PLAN_BUFFER_H diff --git a/include/progress/Progress.h b/include/progress/Progress.h index 6b9c83d532..4a513d94a2 100644 --- a/include/progress/Progress.h +++ b/include/progress/Progress.h @@ -1,58 +1,62 @@ -//Copyright (c) 2018 Ultimaker B.V. -//CuraEngine is released under the terms of the AGPLv3 or higher. +// Copyright (c) 2018 Ultimaker B.V. +// CuraEngine is released under the terms of the AGPLv3 or higher. #ifndef PROGRESS_H #define PROGRESS_H #include +#include "utils/gettime.h" + namespace cura { -class TimeKeeper; +struct LayerIndex; #define N_PROGRESS_STAGES 7 /*! * Class for handling the progress bar and the progress logging. - * + * * The progress bar is based on a single slicing of a rather large model which needs some complex support; * the relative timing of each stage is currently based on that of the slicing of dragon_65_tilted_large.stl */ -class Progress +class Progress { public: /*! - * The stage in the whole slicing process + * The stage in the whole slicing process */ enum class Stage : unsigned int { - START = 0, - SLICING = 1, - PARTS = 2, - INSET_SKIN = 3, - SUPPORT = 4, - EXPORT = 5, - FINISH = 6 + START = 0, + SLICING = 1, + PARTS = 2, + INSET_SKIN = 3, + SUPPORT = 4, + EXPORT = 5, + FINISH = 6 }; + private: - static double times [N_PROGRESS_STAGES]; //!< Time estimates per stage + static double times[N_PROGRESS_STAGES]; //!< Time estimates per stage static std::string names[N_PROGRESS_STAGES]; //!< name of each stage - static double accumulated_times [N_PROGRESS_STAGES]; //!< Time past before each stage + static double accumulated_times[N_PROGRESS_STAGES]; //!< Time past before each stage static double total_timing; //!< An estimate of the total time /*! * Give an estimate between 0 and 1 of how far the process is. - * + * * \param stage The current stage of processing * \param stage_process How far we currently are in the \p stage * \return An estimate of the overall progress. */ static float calcOverallProgress(Stage stage, float stage_progress); + public: static void init(); //!< Initialize some values needed in a fast computation of the progress /*! * Message progress over the CommandSocket and to the terminal (if the command line arg '-p' is provided). - * + * * \param stage The current stage of processing * \param progress_in_stage Any number giving the progress within the stage * \param progress_in_stage_max The maximal value of \p progress_in_stage @@ -60,13 +64,15 @@ class Progress static void messageProgress(Stage stage, int progress_in_stage, int progress_in_stage_max); /*! * Message the progress stage over the command socket. - * + * * \param stage The current stage * \param timeKeeper The stapwatch keeping track of the timings for each stage (optional) */ static void messageProgressStage(Stage stage, TimeKeeper* timeKeeper); + + static void messageProgressLayer(LayerIndex layer_nr, size_t total_layers, double total_time, const TimeKeeper::RegisteredTimes& stages); }; -} // name space cura -#endif//PROGRESS_H +} // namespace cura +#endif // PROGRESS_H diff --git a/include/utils/gettime.h b/include/utils/gettime.h index 319f5d750c..0f011360ad 100644 --- a/include/utils/gettime.h +++ b/include/utils/gettime.h @@ -4,55 +4,42 @@ #ifndef GETTIME_H #define GETTIME_H -#ifdef _WIN32 -#define WIN32_LEAN_AND_MEAN 1 -#include -#else -#ifdef USE_CPU_TIME -#include -#endif - -#include -#include -#include -#endif +#include +#include +#include + +#include namespace cura { -static inline double getTime() -{ -#ifdef _WIN32 - return double(GetTickCount()) / 1000.0; -#else // not __WIN32 -#if USE_CPU_TIME // Use cpu usage time if available, otherwise wall clock time - struct rusage usage; -#ifdef DEBUG - int ret = getrusage(RUSAGE_SELF, &usage); - assert(ret == 0); - ((void)ret); -#else - getrusage(RUSAGE_SELF, &usage); -#endif - double user_time = double(usage.ru_utime.tv_sec) + double(usage.ru_utime.tv_usec) / 1000000.0; - double sys_time = double(usage.ru_stime.tv_sec) + double(usage.ru_stime.tv_usec) / 1000000.0; - return user_time + sys_time; -#else // not USE_CPU_TIME - struct timeval tv; - gettimeofday(&tv, nullptr); - return double(tv.tv_sec) + double(tv.tv_usec) / 1000000.0; -#endif // USE_CPU_TIME -#endif // __WIN32 -} class TimeKeeper { +public: + struct RegisteredTime + { + std::string stage; + double duration; + }; + + using RegisteredTimes = std::vector; + private: - double startTime; + spdlog::stopwatch watch; + double start_time; + RegisteredTimes registered_times; public: TimeKeeper(); double restart(); + + void registerTime(const std::string& stage, double threshold = 0.01); + + const RegisteredTimes& getRegisteredTimes() const + { + return registered_times; + } }; } // namespace cura diff --git a/src/FffGcodeWriter.cpp b/src/FffGcodeWriter.cpp index b99161c1a2..a42d12889d 100644 --- a/src/FffGcodeWriter.cpp +++ b/src/FffGcodeWriter.cpp @@ -7,6 +7,7 @@ #include // numeric_limits #include #include +#include #include #include @@ -168,15 +169,15 @@ void FffGcodeWriter::writeGCode(SliceDataStorage& storage, TimeKeeper& time_keep total_layers, [&storage, total_layers, this](int layer_nr) { - return &processLayer(storage, layer_nr, total_layers); + return std::make_optional(processLayer(storage, layer_nr, total_layers)); }, - [this, total_layers](LayerPlan* gcode_layer) + [this, total_layers](std::optional result_opt) { - Progress::messageProgress(Progress::Stage::EXPORT, std::max(LayerIndex{ 0 }, gcode_layer->getLayerNr()) + 1, total_layers); - layer_plan_buffer.handle(*gcode_layer, gcode); + const ProcessLayerResult& result = result_opt.value(); + Progress::messageProgressLayer(result.layer_plan->getLayerNr(), total_layers, result.total_elapsed_time, result.stages_times); + layer_plan_buffer.handle(*result.layer_plan, gcode); }); - layer_plan_buffer.flush(); Progress::messageProgressStage(Progress::Stage::FINISH, &time_keeper); @@ -945,9 +946,11 @@ void FffGcodeWriter::processRaft(const SliceDataStorage& storage) } } -LayerPlan& FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIndex layer_nr, const size_t total_layers) const +FffGcodeWriter::ProcessLayerResult FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIndex layer_nr, const size_t total_layers) const { spdlog::debug("GcodeWriter processing layer {} of {}", layer_nr, total_layers); + TimeKeeper time_keeper; + spdlog::stopwatch timer_total; const Settings& mesh_group_settings = Application::getInstance().current_slice->scene.current_mesh_group->settings; coord_t layer_thickness = mesh_group_settings.get("layer_height"); @@ -1032,6 +1035,7 @@ LayerPlan& FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIn comb_offset_from_outlines, first_outer_wall_line_width, avoid_distance); + time_keeper.registerTime("Init"); if (include_helper_parts) { @@ -1040,11 +1044,15 @@ LayerPlan& FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIn if (storage.skirt_brim[extruder_nr].size() > 0) { processSkirtBrim(storage, gcode_layer, extruder_nr, layer_nr); + time_keeper.registerTime("Skirt/brim"); } // handle shield(s) first in a layer so that chances are higher that the other nozzle is wiped (for the ooze shield) processOozeShield(storage, gcode_layer); + time_keeper.registerTime("Ooze shield"); + processDraftShield(storage, gcode_layer); + time_keeper.registerTime("Draft shield"); } const size_t support_roof_extruder_nr = mesh_group_settings.get("support_roof_extruder_nr").extruder_nr; @@ -1065,10 +1073,12 @@ LayerPlan& FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIn if (extruder_nr != extruder_order.front() || (extruder_order.size() == 1 && layer_nr >= 0) || extruder_nr == 0) { setExtruder_addPrime(storage, gcode_layer, extruder_nr); + time_keeper.registerTime("Prime tower pre"); } if (include_helper_parts && (extruder_nr == support_infill_extruder_nr || extruder_nr == support_roof_extruder_nr || extruder_nr == support_bottom_extruder_nr)) { addSupportToGCode(storage, gcode_layer, extruder_nr); + time_keeper.registerTime("Supports"); } if (layer_nr >= 0) { @@ -1088,6 +1098,7 @@ LayerPlan& FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIn { addMeshLayerToGCode(storage, mesh, extruder_nr, mesh_config, gcode_layer); } + time_keeper.registerTime(fmt::format("Mesh {}", mesh_idx)); } } // Always print a prime tower before switching extruder. Unless: @@ -1096,12 +1107,17 @@ LayerPlan& FffGcodeWriter::processLayer(const SliceDataStorage& storage, LayerIn if (extruder_nr != extruder_order.back() && layer_nr >= 0) { setExtruder_addPrime(storage, gcode_layer, extruder_nr); + time_keeper.registerTime("Prime tower post"); } } gcode_layer.applyModifyPlugin(); + time_keeper.registerTime("Modify plugin"); + gcode_layer.applyBackPressureCompensation(); - return gcode_layer; + time_keeper.registerTime("Back pressure comp."); + + return { &gcode_layer, timer_total.elapsed().count(), time_keeper.getRegisteredTimes() }; } bool FffGcodeWriter::getExtruderNeedPrimeBlobDuringFirstLayer(const SliceDataStorage& storage, const size_t extruder_nr) const @@ -2036,8 +2052,8 @@ bool FffGcodeWriter::processSingleLayerInfill( else // So walls_generated must be true. { std::vector* start_paths = &wall_tool_paths[rand() % wall_tool_paths.size()]; - while (start_paths->empty() || (*start_paths)[0].empty()) // We know for sure (because walls_generated) that one of them is not empty. So randomise until we hit it. - // Should almost always be very quick. + while (start_paths->empty() || (*start_paths)[0].empty()) // We know for sure (because walls_generated) that one of them is not empty. So randomise until we hit + // it. Should almost always be very quick. { start_paths = &wall_tool_paths[rand() % wall_tool_paths.size()]; } @@ -2169,8 +2185,8 @@ bool FffGcodeWriter::partitionInfillBySkinAbove( } else // this layer is the 1st layer above the layer whose infill we're printing { - // add this layer's skin region without subtracting the overlap but still make a gap between this skin region and what has been accumulated so far - // we do this so that these skin region edges will definitely have infill walls below them + // add this layer's skin region without subtracting the overlap but still make a gap between this skin region and what has been accumulated so + // far we do this so that these skin region edges will definitely have infill walls below them // looking from the side, if the combined regions so far look like this... // @@ -2201,8 +2217,8 @@ bool FffGcodeWriter::partitionInfillBySkinAbove( } } - // the shrink/expand here is to remove regions of infill below skin that are narrower than the width of the infill walls otherwise the infill walls could merge and form a - // bump + // the shrink/expand here is to remove regions of infill below skin that are narrower than the width of the infill walls otherwise the infill walls could merge and form + // a bump infill_below_skin = skin_above_combined.intersection(part.infill_area_per_combine_per_density.back().front()).offset(-infill_line_width).offset(infill_line_width); constexpr bool remove_small_holes_from_infill_below_skin = true; diff --git a/src/MeshGroup.cpp b/src/MeshGroup.cpp index 1516e64190..84ef4d4923 100644 --- a/src/MeshGroup.cpp +++ b/src/MeshGroup.cpp @@ -1,6 +1,8 @@ // Copyright (c) 2023 UltiMaker // CuraEngine is released under the terms of the AGPLv3 or higher +#include "MeshGroup.h" + #include #include #include @@ -10,7 +12,6 @@ #include #include -#include "MeshGroup.h" #include "settings/types/Ratio.h" //For the shrinkage percentage and scale factor. #include "utils/FMatrix4x3.h" //To transform the input meshes for shrinkage compensation and to align in command line mode. #include "utils/floatpoint.h" //To accept incoming meshes with floating point vertices. @@ -48,7 +49,8 @@ Point3 MeshGroup::min() const Point3 ret(std::numeric_limits::max(), std::numeric_limits::max(), std::numeric_limits::max()); for (const Mesh& mesh : meshes) { - if (mesh.settings.get("infill_mesh") || mesh.settings.get("cutting_mesh") || mesh.settings.get("anti_overhang_mesh")) // Don't count pieces that are not printed. + if (mesh.settings.get("infill_mesh") || mesh.settings.get("cutting_mesh") + || mesh.settings.get("anti_overhang_mesh")) // Don't count pieces that are not printed. { continue; } @@ -69,7 +71,8 @@ Point3 MeshGroup::max() const Point3 ret(std::numeric_limits::min(), std::numeric_limits::min(), std::numeric_limits::min()); for (const Mesh& mesh : meshes) { - if (mesh.settings.get("infill_mesh") || mesh.settings.get("cutting_mesh") || mesh.settings.get("anti_overhang_mesh")) // Don't count pieces that are not printed. + if (mesh.settings.get("infill_mesh") || mesh.settings.get("cutting_mesh") + || mesh.settings.get("anti_overhang_mesh")) // Don't count pieces that are not printed. { continue; } @@ -112,7 +115,9 @@ void MeshGroup::finalize() } mesh.translate(mesh_offset + meshgroup_offset); } - scaleFromBottom(settings.get("material_shrinkage_percentage_xy"), settings.get("material_shrinkage_percentage_z")); // Compensate for the shrinkage of the material. + scaleFromBottom( + settings.get("material_shrinkage_percentage_xy"), + settings.get("material_shrinkage_percentage_z")); // Compensate for the shrinkage of the material. for (const auto& [idx, mesh] : meshes | ranges::views::enumerate) { scripta::log(fmt::format("mesh_{}", idx), mesh, SectionType::NA); @@ -285,7 +290,7 @@ bool loadMeshIntoMeshGroup(MeshGroup* meshgroup, const char* filename, const FMa if (loadMeshSTL(&mesh, filename, transformation)) // Load it! If successful... { meshgroup->meshes.push_back(mesh); - spdlog::info("loading '{}' took {:3} seconds", filename, load_timer.restart()); + spdlog::info("loading '{}' took {:03.3f} seconds", filename, load_timer.restart()); return true; } } diff --git a/src/Scene.cpp b/src/Scene.cpp index ff4baf9adc..ac50185b6d 100644 --- a/src/Scene.cpp +++ b/src/Scene.cpp @@ -1,11 +1,12 @@ // Copyright (c) 2023 UltiMaker // CuraEngine is released under the terms of the AGPLv3 or higher +#include "Scene.h" + #include #include "Application.h" #include "FffProcessor.h" //To start a slice. -#include "Scene.h" #include "communication/Communication.h" //To flush g-code and layer view when we're done. #include "progress/Progress.h" #include "sliceDataStorage.h" @@ -13,7 +14,9 @@ namespace cura { -Scene::Scene(const size_t num_mesh_groups) : mesh_groups(num_mesh_groups), current_mesh_group(mesh_groups.begin()) +Scene::Scene(const size_t num_mesh_groups) + : mesh_groups(num_mesh_groups) + , current_mesh_group(mesh_groups.begin()) { for (MeshGroup& mesh_group : mesh_groups) { @@ -78,7 +81,7 @@ void Scene::processMeshGroup(MeshGroup& mesh_group) if (empty) { Progress::messageProgress(Progress::Stage::FINISH, 1, 1); // 100% on this meshgroup - spdlog::info("Total time elapsed {:3}s.", time_keeper_total.restart()); + spdlog::info("Total time elapsed {:03.3f}s", time_keeper_total.restart()); return; } @@ -94,7 +97,7 @@ void Scene::processMeshGroup(MeshGroup& mesh_group) Progress::messageProgress(Progress::Stage::FINISH, 1, 1); // 100% on this meshgroup Application::getInstance().communication->flushGCode(); Application::getInstance().communication->sendOptimizedLayerData(); - spdlog::info("Total time elapsed {:3}s.\n", time_keeper_total.restart()); + spdlog::info("Total time elapsed {:03.3f}s\n", time_keeper_total.restart()); } -} // namespace cura \ No newline at end of file +} // namespace cura diff --git a/src/progress/Progress.cpp b/src/progress/Progress.cpp index 62687044c6..fb3331bc02 100644 --- a/src/progress/Progress.cpp +++ b/src/progress/Progress.cpp @@ -1,49 +1,40 @@ // Copyright (c) 2022 Ultimaker B.V. // CuraEngine is released under the terms of the AGPLv3 or higher +#include "progress/Progress.h" + #include #include #include "Application.h" //To get the communication channel to send progress through. #include "communication/Communication.h" //To send progress through the communication channel. -#include "progress/Progress.h" #include "utils/gettime.h" namespace cura { double Progress::times[] = { - 0.0, // START = 0, - 5.269, // SLICING = 1, - 1.533, // PARTS = 2, + 0.0, // START = 0, + 5.269, // SLICING = 1, + 1.533, // PARTS = 2, 71.811, // INSET_SKIN = 3 - 51.009, // SUPPORT = 4, - 154.62, // EXPORT = 5, - 0.1 // FINISH = 6 -}; -std::string Progress::names [] = -{ - "start", - "slice", - "layerparts", - "inset+skin", - "support", - "export", - "process" + 51.009, // SUPPORT = 4, + 154.62, // EXPORT = 5, + 0.1 // FINISH = 6 }; +std::string Progress::names[] = { "start", "slice", "layerparts", "inset+skin", "support", "export", "process" }; -double Progress::accumulated_times [N_PROGRESS_STAGES] = {-1}; +double Progress::accumulated_times[N_PROGRESS_STAGES] = { -1 }; double Progress::total_timing = -1; float Progress::calcOverallProgress(Stage stage, float stage_progress) { assert(stage_progress <= 1.0); assert(stage_progress >= 0.0); - return ( accumulated_times[(int)stage] + stage_progress * times[(int)stage] ) / total_timing; + return (accumulated_times[(int)stage] + stage_progress * times[(int)stage]) / total_timing; } - void Progress::init() { double accumulated_time = 0; @@ -59,8 +50,6 @@ void Progress::messageProgress(Progress::Stage stage, int progress_in_stage, int { float percentage = calcOverallProgress(stage, float(progress_in_stage) / float(progress_in_stage_max)); Application::getInstance().communication->sendProgress(percentage); - - // logProgress(names[(int)stage].c_str(), progress_in_stage, progress_in_stage_max, percentage); FIXME: use different sink } void Progress::messageProgressStage(Progress::Stage stage, TimeKeeper* time_keeper) @@ -69,13 +58,13 @@ void Progress::messageProgressStage(Progress::Stage stage, TimeKeeper* time_keep { if ((int)stage > 0) { - spdlog::info("Progress: {} accomplished in {:3}s", names[(int)stage - 1], time_keeper->restart()); + spdlog::info("Progress: {} accomplished in {:03.3f}s", names[(int)stage - 1], time_keeper->restart()); } else { time_keeper->restart(); } - + if ((int)stage < (int)Stage::FINISH) { spdlog::info("Starting {}...", names[(int)stage]); @@ -83,4 +72,29 @@ void Progress::messageProgressStage(Progress::Stage stage, TimeKeeper* time_keep } } -}// namespace cura \ No newline at end of file +void Progress::messageProgressLayer(LayerIndex layer_nr, size_t total_layers, double total_time, const TimeKeeper::RegisteredTimes& stages) +{ + messageProgress(Stage::EXPORT, std::max(layer_nr.value, LayerIndex::value_type(0)) + 1, total_layers); + + spdlog::info("+---- Layer export [{}] accomplished in {:03.3f}s", layer_nr.value, total_time); + + size_t padding = 0; + auto iterator_max_size = std::max_element( + stages.begin(), + stages.end(), + [](const TimeKeeper::RegisteredTime& time1, const TimeKeeper::RegisteredTime& time2) + { + return time1.stage.size() < time2.stage.size(); + }); + if (iterator_max_size != stages.end()) + { + padding = iterator_max_size->stage.size(); + + for (const TimeKeeper::RegisteredTime& time : stages) + { + spdlog::info("| *{}:{} {:03.3f}s", time.stage, std::string(padding - time.stage.size(), ' '), time.duration); + } + } +} + +} // namespace cura diff --git a/src/slicer.cpp b/src/slicer.cpp index 6b1ac7ea4d..f5127833bc 100644 --- a/src/slicer.cpp +++ b/src/slicer.cpp @@ -3,6 +3,13 @@ #include "slicer.h" +#include // remove_if +#include +#include + +#include +#include + #include "Application.h" #include "Slice.h" #include "plugins/slots.h" @@ -15,13 +22,6 @@ #include "utils/gettime.h" #include "utils/section_type.h" -#include -#include - -#include // remove_if -#include -#include - namespace cura { @@ -825,11 +825,11 @@ Slicer::Slicer(Mesh* i_mesh, const coord_t thickness, const size_t slice_layer_c buildSegments(*mesh, zbbox, slicing_tolerance, layers); - spdlog::info("Slice of mesh took {:3} seconds", slice_timer.restart()); + spdlog::info("Slice of mesh took {:03.3f} seconds", slice_timer.restart()); makePolygons(*i_mesh, slicing_tolerance, layers); scripta::log("sliced_polygons", layers, SectionType::NA); - spdlog::info("Make polygons took {:3} seconds", slice_timer.restart()); + spdlog::info("Make polygons took {:03.3f} seconds", slice_timer.restart()); } void Slicer::buildSegments(const Mesh& mesh, const std::vector>& zbbox, const SlicingTolerance& slicing_tolerance, std::vector& layers) diff --git a/src/utils/gettime.cpp b/src/utils/gettime.cpp index bfd665abaa..a7d8303857 100644 --- a/src/utils/gettime.cpp +++ b/src/utils/gettime.cpp @@ -1,21 +1,31 @@ -//Copyright (c) 2022 Ultimaker B.V. -//CuraEngine is released under the terms of the AGPLv3 or higher. +// Copyright (c) 2022 Ultimaker B.V. +// CuraEngine is released under the terms of the AGPLv3 or higher. #include "utils/gettime.h" +#include + namespace cura { - + TimeKeeper::TimeKeeper() { - restart(); } double TimeKeeper::restart() { - double ret = getTime() - startTime; - startTime = getTime(); + double ret = watch.elapsed().count(); + watch.reset(); return ret; } -}//namespace cura \ No newline at end of file +void TimeKeeper::registerTime(const std::string& stage, double threshold) +{ + double duration = restart(); + if (duration >= threshold) + { + registered_times.emplace_back(RegisteredTime{ stage, duration }); + } +} + +} // namespace cura From a58cb53efd3dd441c083218ad27ad073ccc36af2 Mon Sep 17 00:00:00 2001 From: Jelle Spijker Date: Thu, 2 Nov 2023 17:56:38 +0100 Subject: [PATCH 03/10] Allow scripta to construct layermap with raft See: https://github.com/Ultimaker/Scripta/pull/7 --- src/slicer.cpp | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/src/slicer.cpp b/src/slicer.cpp index 6b1ac7ea4d..62e8e3d57d 100644 --- a/src/slicer.cpp +++ b/src/slicer.cpp @@ -819,7 +819,15 @@ Slicer::Slicer(Mesh* i_mesh, const coord_t thickness, const size_t slice_layer_c TimeKeeper slice_timer; layers = buildLayersWithHeight(slice_layer_count, slicing_tolerance, initial_layer_thickness, thickness, use_variable_layer_heights, adaptive_layers); - scripta::setAll(layers); + scripta::setAll(layers, + static_cast(mesh->settings.get("adhesion_type")), + mesh->settings.get("raft_surface_layers"), + mesh->settings.get("raft_surface_thickness"), + mesh->settings.get("raft_interface_layers"), + mesh->settings.get("raft_interface_thickness"), + mesh->settings.get("raft_base_thickness"), + mesh->settings.get("raft_airgap"), + mesh->settings.get("layer_0_z_overlap")); std::vector> zbbox = buildZHeightsForFaces(*mesh); From db79053f1166ab383a5beb71c8d9b41c64ccc36c Mon Sep 17 00:00:00 2001 From: wawanbreton Date: Fri, 3 Nov 2023 11:00:24 +0000 Subject: [PATCH 04/10] Applied clang-format. --- src/slicer.cpp | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/src/slicer.cpp b/src/slicer.cpp index 485a1d5ed5..2758d133f0 100644 --- a/src/slicer.cpp +++ b/src/slicer.cpp @@ -819,15 +819,16 @@ Slicer::Slicer(Mesh* i_mesh, const coord_t thickness, const size_t slice_layer_c TimeKeeper slice_timer; layers = buildLayersWithHeight(slice_layer_count, slicing_tolerance, initial_layer_thickness, thickness, use_variable_layer_heights, adaptive_layers); - scripta::setAll(layers, - static_cast(mesh->settings.get("adhesion_type")), - mesh->settings.get("raft_surface_layers"), - mesh->settings.get("raft_surface_thickness"), - mesh->settings.get("raft_interface_layers"), - mesh->settings.get("raft_interface_thickness"), - mesh->settings.get("raft_base_thickness"), - mesh->settings.get("raft_airgap"), - mesh->settings.get("layer_0_z_overlap")); + scripta::setAll( + layers, + static_cast(mesh->settings.get("adhesion_type")), + mesh->settings.get("raft_surface_layers"), + mesh->settings.get("raft_surface_thickness"), + mesh->settings.get("raft_interface_layers"), + mesh->settings.get("raft_interface_thickness"), + mesh->settings.get("raft_base_thickness"), + mesh->settings.get("raft_airgap"), + mesh->settings.get("layer_0_z_overlap")); std::vector> zbbox = buildZHeightsForFaces(*mesh); From bca565bdfe97ebc874989f362c24bb3f879dc2cd Mon Sep 17 00:00:00 2001 From: Erwan MATHIEU Date: Tue, 7 Nov 2023 10:54:47 +0100 Subject: [PATCH 05/10] Time report improvements CURA-11255 --- include/progress/Progress.h | 14 ++++++++++- src/progress/Progress.cpp | 50 +++++++++++++++++++++++++------------ 2 files changed, 47 insertions(+), 17 deletions(-) diff --git a/include/progress/Progress.h b/include/progress/Progress.h index 4a513d94a2..619632a1f0 100644 --- a/include/progress/Progress.h +++ b/include/progress/Progress.h @@ -43,6 +43,7 @@ class Progress static std::string names[N_PROGRESS_STAGES]; //!< name of each stage static double accumulated_times[N_PROGRESS_STAGES]; //!< Time past before each stage static double total_timing; //!< An estimate of the total time + static std::optional first_skipped_layer; //!< The index of the layer for which we skipped time reporting /*! * Give an estimate between 0 and 1 of how far the process is. * @@ -62,6 +63,7 @@ class Progress * \param progress_in_stage_max The maximal value of \p progress_in_stage */ static void messageProgress(Stage stage, int progress_in_stage, int progress_in_stage_max); + /*! * Message the progress stage over the command socket. * @@ -70,7 +72,17 @@ class Progress */ static void messageProgressStage(Stage stage, TimeKeeper* timeKeeper); - static void messageProgressLayer(LayerIndex layer_nr, size_t total_layers, double total_time, const TimeKeeper::RegisteredTimes& stages); + /*! + * Message the layer progress over the command socket and into logging output. + * + * \param layer_nr The processed layer number + * \param total_layers The total number of layers to be processed + * \param total_time The total layer processing time, in seconds + * \param stage The detailed stages time reporting for this layer + * \param skip_threshold The time threshold under which we consider that the full layer time reporting should be skipped + * because it is not relevant + */ + static void messageProgressLayer(LayerIndex layer_nr, size_t total_layers, double total_time, const TimeKeeper::RegisteredTimes& stages, double skip_threshold = 0.1); }; diff --git a/src/progress/Progress.cpp b/src/progress/Progress.cpp index fb3331bc02..85194808b0 100644 --- a/src/progress/Progress.cpp +++ b/src/progress/Progress.cpp @@ -5,6 +5,7 @@ #include +#include #include #include "Application.h" //To get the communication channel to send progress through. @@ -27,6 +28,7 @@ std::string Progress::names[] = { "start", "slice", "layerparts", "inset+skin", double Progress::accumulated_times[N_PROGRESS_STAGES] = { -1 }; double Progress::total_timing = -1; +std::optional Progress::first_skipped_layer{}; float Progress::calcOverallProgress(Stage stage, float stage_progress) { @@ -72,27 +74,43 @@ void Progress::messageProgressStage(Progress::Stage stage, TimeKeeper* time_keep } } -void Progress::messageProgressLayer(LayerIndex layer_nr, size_t total_layers, double total_time, const TimeKeeper::RegisteredTimes& stages) +void Progress::messageProgressLayer(LayerIndex layer_nr, size_t total_layers, double total_time, const TimeKeeper::RegisteredTimes& stages, double skip_threshold) { - messageProgress(Stage::EXPORT, std::max(layer_nr.value, LayerIndex::value_type(0)) + 1, total_layers); - - spdlog::info("+---- Layer export [{}] accomplished in {:03.3f}s", layer_nr.value, total_time); - - size_t padding = 0; - auto iterator_max_size = std::max_element( - stages.begin(), - stages.end(), - [](const TimeKeeper::RegisteredTime& time1, const TimeKeeper::RegisteredTime& time2) + if (total_time < skip_threshold) + { + if (! first_skipped_layer) { - return time1.stage.size() < time2.stage.size(); - }); - if (iterator_max_size != stages.end()) + first_skipped_layer = layer_nr; + } + } + else { - padding = iterator_max_size->stage.size(); + if (first_skipped_layer) + { + spdlog::info("Skipped time reporting for layers [{}...{}]", first_skipped_layer.value().value, layer_nr.value); + first_skipped_layer.reset(); + } + + messageProgress(Stage::EXPORT, std::max(layer_nr.value, LayerIndex::value_type(0)) + 1, total_layers); - for (const TimeKeeper::RegisteredTime& time : stages) + spdlog::info("┌ Layer export [{}] accomplished in {:03.3f}s", layer_nr.value, total_time); + + size_t padding = 0; + auto iterator_max_size = std::max_element( + stages.begin(), + stages.end(), + [](const TimeKeeper::RegisteredTime& time1, const TimeKeeper::RegisteredTime& time2) + { + return time1.stage.size() < time2.stage.size(); + }); + if (iterator_max_size != stages.end()) { - spdlog::info("| *{}:{} {:03.3f}s", time.stage, std::string(padding - time.stage.size(), ' '), time.duration); + padding = iterator_max_size->stage.size(); + + for (auto [index, time] : stages | ranges::view::enumerate) + { + spdlog::info("{}── {}:{} {:03.3f}s", index < stages.size() - 1 ? "├" : "└", time.stage, std::string(padding - time.stage.size(), ' '), time.duration); + } } } } From c07a0a170867b3c90dcb88c6800927d1afcce041 Mon Sep 17 00:00:00 2001 From: Erwan MATHIEU Date: Tue, 7 Nov 2023 12:32:17 +0100 Subject: [PATCH 06/10] Fix unit test --- tests/integration/SlicePhaseTest.cpp | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/tests/integration/SlicePhaseTest.cpp b/tests/integration/SlicePhaseTest.cpp index 34e46dc809..75d66899b8 100644 --- a/tests/integration/SlicePhaseTest.cpp +++ b/tests/integration/SlicePhaseTest.cpp @@ -1,6 +1,10 @@ // Copyright (c) 2023 UltiMaker // CuraEngine is released under the terms of the AGPLv3 or higher +#include + +#include + #include "Application.h" // To set up a slice with settings. #include "Slice.h" // To set up a scene to slice. #include "slicer.h" // Starts the slicing phase that we want to test. @@ -8,8 +12,6 @@ #include "utils/FMatrix4x3.h" // To load STL files. #include "utils/polygon.h" // Creating polygons to compare to sliced layers. #include "utils/polygonUtils.h" // Comparing similarity of polygons. -#include -#include namespace cura { @@ -35,6 +37,13 @@ class SlicePhaseTest : public testing::Test scene.settings.add("slicing_tolerance", "middle"); scene.settings.add("layer_height_0", "0.2"); scene.settings.add("layer_height", "0.1"); + scene.settings.add("layer_0_z_overlap", "0.0"); + scene.settings.add("raft_airgap", "0.0"); + scene.settings.add("raft_base_thickness", "0.2"); + scene.settings.add("raft_interface_thickness", "0.2"); + scene.settings.add("raft_interface_layers", "1"); + scene.settings.add("raft_surface_thickness", "0.2"); + scene.settings.add("raft_surface_layers", "1"); scene.settings.add("magic_mesh_surface_mode", "normal"); scene.settings.add("meshfix_extensive_stitching", "false"); scene.settings.add("meshfix_keep_open_polygons", "false"); @@ -51,6 +60,7 @@ class SlicePhaseTest : public testing::Test scene.settings.add("anti_overhang_mesh", "false"); scene.settings.add("cutting_mesh", "false"); scene.settings.add("infill_mesh", "false"); + scene.settings.add("adhesion_type", "none"); } }; @@ -121,7 +131,8 @@ TEST_F(SlicePhaseTest, Cylinder1000) const FMatrix4x3 transformation; // Path to cylinder1000.stl is relative to CMAKE_CURRENT_SOURCE_DIR/tests. - ASSERT_TRUE(loadMeshIntoMeshGroup(&mesh_group, std::filesystem::path(__FILE__).parent_path().append("resources/cylinder1000.stl").string().c_str(), transformation, scene.settings)); + ASSERT_TRUE( + loadMeshIntoMeshGroup(&mesh_group, std::filesystem::path(__FILE__).parent_path().append("resources/cylinder1000.stl").string().c_str(), transformation, scene.settings)); EXPECT_EQ(mesh_group.meshes.size(), 1); Mesh& cylinder_mesh = mesh_group.meshes[0]; @@ -162,4 +173,4 @@ TEST_F(SlicePhaseTest, Cylinder1000) } } -} // namespace cura \ No newline at end of file +} // namespace cura From 3cfce8350ba204f0229a85907ca575e1522089d6 Mon Sep 17 00:00:00 2001 From: Jelle Spijker Date: Wed, 8 Nov 2023 10:13:43 +0100 Subject: [PATCH 07/10] Add missing include `optional` --- src/progress/Progress.cpp | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/progress/Progress.cpp b/src/progress/Progress.cpp index 85194808b0..d0c3e9203a 100644 --- a/src/progress/Progress.cpp +++ b/src/progress/Progress.cpp @@ -1,9 +1,10 @@ -// Copyright (c) 2022 Ultimaker B.V. +// Copyright (c) 2023 UltiMaker // CuraEngine is released under the terms of the AGPLv3 or higher #include "progress/Progress.h" #include +#include #include #include From 138d6cdefcce91b4bc5fa8e379ec322b756c2eb9 Mon Sep 17 00:00:00 2001 From: Jelle Spijker Date: Wed, 8 Nov 2023 10:14:31 +0100 Subject: [PATCH 08/10] Use correct namespace for `ranges::views` --- src/progress/Progress.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/progress/Progress.cpp b/src/progress/Progress.cpp index d0c3e9203a..6af743785d 100644 --- a/src/progress/Progress.cpp +++ b/src/progress/Progress.cpp @@ -108,7 +108,7 @@ void Progress::messageProgressLayer(LayerIndex layer_nr, size_t total_layers, do { padding = iterator_max_size->stage.size(); - for (auto [index, time] : stages | ranges::view::enumerate) + for (auto [index, time] : stages | ranges::views::enumerate) { spdlog::info("{}── {}:{} {:03.3f}s", index < stages.size() - 1 ? "├" : "└", time.stage, std::string(padding - time.stage.size(), ' '), time.duration); } From eeb93cfaa3bd7466a4b519206cc3e51423dd13a6 Mon Sep 17 00:00:00 2001 From: Jelle Spijker Date: Wed, 8 Nov 2023 10:47:28 +0100 Subject: [PATCH 09/10] Refactor Progress class and improve type safety This refactor cleans up the Progress class and enhances type safety. It replaces raw C-style arrays with std::array, which guarantees type safety and prevents out-of-bound access. The type of several variables and methods has also been changed from int and float to size_t and double to increase precision. --- include/progress/Progress.h | 26 +++++++++++++++++------- src/progress/Progress.cpp | 40 +++++++++++++------------------------ 2 files changed, 33 insertions(+), 33 deletions(-) diff --git a/include/progress/Progress.h b/include/progress/Progress.h index 619632a1f0..ae829867bb 100644 --- a/include/progress/Progress.h +++ b/include/progress/Progress.h @@ -1,10 +1,13 @@ -// Copyright (c) 2018 Ultimaker B.V. -// CuraEngine is released under the terms of the AGPLv3 or higher. +// Copyright (c) 2023 UltiMaker +// CuraEngine is released under the terms of the AGPLv3 or higher #ifndef PROGRESS_H #define PROGRESS_H +#include #include +#include +#include #include "utils/gettime.h" @@ -13,7 +16,7 @@ namespace cura struct LayerIndex; -#define N_PROGRESS_STAGES 7 +static constexpr size_t N_PROGRESS_STAGES = 7; /*! * Class for handling the progress bar and the progress logging. @@ -39,9 +42,18 @@ class Progress }; private: - static double times[N_PROGRESS_STAGES]; //!< Time estimates per stage - static std::string names[N_PROGRESS_STAGES]; //!< name of each stage - static double accumulated_times[N_PROGRESS_STAGES]; //!< Time past before each stage + static constexpr std::array times{ + 0.0, // START = 0, + 5.269, // SLICING = 1, + 1.533, // PARTS = 2, + 71.811, // INSET_SKIN = 3 + 51.009, // SUPPORT = 4, + 154.62, // EXPORT = 5, + 0.1 // FINISH = 6 + }; + + static constexpr std::array names{ "start", "slice", "layerparts", "inset+skin", "support", "export", "process" }; + static std::array accumulated_times; //!< Time past before each stage static double total_timing; //!< An estimate of the total time static std::optional first_skipped_layer; //!< The index of the layer for which we skipped time reporting /*! @@ -51,7 +63,7 @@ class Progress * \param stage_process How far we currently are in the \p stage * \return An estimate of the overall progress. */ - static float calcOverallProgress(Stage stage, float stage_progress); + static double calcOverallProgress(Stage stage, double stage_progress); public: static void init(); //!< Initialize some values needed in a fast computation of the progress diff --git a/src/progress/Progress.cpp b/src/progress/Progress.cpp index 6af743785d..be6a688813 100644 --- a/src/progress/Progress.cpp +++ b/src/progress/Progress.cpp @@ -15,62 +15,50 @@ namespace cura { - -double Progress::times[] = { - 0.0, // START = 0, - 5.269, // SLICING = 1, - 1.533, // PARTS = 2, - 71.811, // INSET_SKIN = 3 - 51.009, // SUPPORT = 4, - 154.62, // EXPORT = 5, - 0.1 // FINISH = 6 -}; -std::string Progress::names[] = { "start", "slice", "layerparts", "inset+skin", "support", "export", "process" }; - -double Progress::accumulated_times[N_PROGRESS_STAGES] = { -1 }; +std::array Progress::accumulated_times = { -1 }; double Progress::total_timing = -1; std::optional Progress::first_skipped_layer{}; -float Progress::calcOverallProgress(Stage stage, float stage_progress) +double Progress::calcOverallProgress(Stage stage, double stage_progress) { assert(stage_progress <= 1.0); assert(stage_progress >= 0.0); - return (accumulated_times[(int)stage] + stage_progress * times[(int)stage]) / total_timing; + return (accumulated_times.at(static_cast(stage)) + stage_progress * times.at(static_cast(stage))) / total_timing; } void Progress::init() { double accumulated_time = 0; - for (int stage = 0; stage < N_PROGRESS_STAGES; stage++) + for (size_t stage = 0; stage < N_PROGRESS_STAGES; stage++) { - accumulated_times[(int)stage] = accumulated_time; - accumulated_time += times[(int)stage]; + accumulated_times.at(static_cast(stage)) = accumulated_time; + accumulated_time += times.at(static_cast(stage)); } total_timing = accumulated_time; } void Progress::messageProgress(Progress::Stage stage, int progress_in_stage, int progress_in_stage_max) { - float percentage = calcOverallProgress(stage, float(progress_in_stage) / float(progress_in_stage_max)); - Application::getInstance().communication->sendProgress(percentage); + double percentage = calcOverallProgress(stage, static_cast(progress_in_stage / static_cast(progress_in_stage_max))); + Application::getInstance().communication->sendProgress(static_cast(percentage)); } void Progress::messageProgressStage(Progress::Stage stage, TimeKeeper* time_keeper) { - if (time_keeper) + if (time_keeper != nullptr) { - if ((int)stage > 0) + if (static_cast(stage) > 0) { - spdlog::info("Progress: {} accomplished in {:03.3f}s", names[(int)stage - 1], time_keeper->restart()); + spdlog::info("Progress: {} accomplished in {:03.3f}s", names.at(static_cast(stage) - 1), time_keeper->restart()); } else { time_keeper->restart(); } - if ((int)stage < (int)Stage::FINISH) + if (static_cast(stage) < static_cast(Stage::FINISH)) { - spdlog::info("Starting {}...", names[(int)stage]); + spdlog::info("Starting {}...", names.at(static_cast(stage))); } } } @@ -108,7 +96,7 @@ void Progress::messageProgressLayer(LayerIndex layer_nr, size_t total_layers, do { padding = iterator_max_size->stage.size(); - for (auto [index, time] : stages | ranges::views::enumerate) + for (const auto& [index, time] : stages | ranges::views::enumerate) { spdlog::info("{}── {}:{} {:03.3f}s", index < stages.size() - 1 ? "├" : "└", time.stage, std::string(padding - time.stage.size(), ' '), time.duration); } From 0c3e9d0c492d15068f8afe9aa2743e5e068e7cbd Mon Sep 17 00:00:00 2001 From: jellespijker Date: Wed, 8 Nov 2023 11:22:57 +0000 Subject: [PATCH 10/10] Applied clang-format. --- include/progress/Progress.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/progress/Progress.h b/include/progress/Progress.h index ae829867bb..c1e20cc6c7 100644 --- a/include/progress/Progress.h +++ b/include/progress/Progress.h @@ -5,9 +5,9 @@ #define PROGRESS_H #include +#include #include #include -#include #include "utils/gettime.h"