Skip to content

Commit

Permalink
Detailed timing logging for layer export
Browse files Browse the repository at this point in the history 
CURA-11255
  • Loading branch information
@wawanbreton
wawanbreton committed Nov 2, 2023
1 parent ea0436e commit 13a059e
Show file tree
Hide file tree
Showing 10 changed files with 175 additions and 128 deletions.
11 changes: 9 additions & 2 deletions include/FffGcodeWriter.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand All @@ -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.
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand Down
9 changes: 4 additions & 5 deletions include/LayerPlanBuffer.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,16 +4,16 @@
#ifndef LAYER_PLAN_BUFFER_H
#define LAYER_PLAN_BUFFER_H

#include <list>
#include <vector>

#include "ExtruderPlan.h"
#include "LayerPlan.h"
#include "Preheat.h"
#include "gcodeExport.h"
#include "settings/Settings.h"
#include "settings/types/Duration.h"

#include <list>
#include <vector>

namespace cura
{

Expand All @@ -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.
Expand Down Expand Up @@ -215,4 +214,4 @@ class LayerPlanBuffer

} // namespace cura

#endif // LAYER_PLAN_BUFFER_H
#endif // LAYER_PLAN_BUFFER_H
46 changes: 26 additions & 20 deletions include/progress/Progress.h
View file
Original file line number Diff line number Diff line change
@@ -1,72 +1,78 @@
//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 <string>

#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
*/
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
61 changes: 24 additions & 37 deletions include/utils/gettime.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,55 +4,42 @@
#ifndef GETTIME_H
#define GETTIME_H

#ifdef _WIN32
#define WIN32_LEAN_AND_MEAN 1
#include <windows.h>
#else
#ifdef USE_CPU_TIME
#include <sys/resource.h>
#endif

#include <cassert>
#include <stddef.h>
#include <sys/time.h>
#endif
#include <chrono>
#include <string>
#include <vector>

#include <spdlog/stopwatch.h>

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<RegisteredTime>;

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
Expand Down
42 changes: 29 additions & 13 deletions src/FffGcodeWriter.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
#include <limits> // numeric_limits
#include <list>
#include <memory>
#include <numeric>
#include <optional>
#include <unordered_set>

Expand Down Expand Up @@ -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<ProcessLayerResult> 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);
Expand Down Expand Up @@ -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<coord_t>("layer_height");
Expand Down Expand Up @@ -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)
{
Expand All @@ -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<ExtruderTrain&>("support_roof_extruder_nr").extruder_nr;
Expand All @@ -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)
{
Expand All @@ -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:
Expand All @@ -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
Expand Down Expand Up @@ -2036,8 +2052,8 @@ bool FffGcodeWriter::processSingleLayerInfill(
else // So walls_generated must be true.
{
std::vector<VariableWidthLines>* 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()];
}
Expand Down Expand Up @@ -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...
//
Expand Down Expand Up @@ -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;
Expand Down
Loading

0 comments on commit 13a059e

Please sign in to comment.