From 08383becdc707e5dfc2add9698b4ae5245e754df Mon Sep 17 00:00:00 2001 From: SoftFever Date: Fri, 3 Jul 2026 11:10:21 +0800 Subject: [PATCH] fix time --- src/libslic3r/GCode/GCodeProcessor.cpp | 95 +++++++++++-- src/libslic3r/GCode/GCodeProcessor.hpp | 18 ++- tests/fff_print/CMakeLists.txt | 1 + tests/fff_print/test_gcode_timing.cpp | 185 +++++++++++++++++++++++++ 4 files changed, 286 insertions(+), 13 deletions(-) create mode 100644 tests/fff_print/test_gcode_timing.cpp diff --git a/src/libslic3r/GCode/GCodeProcessor.cpp b/src/libslic3r/GCode/GCodeProcessor.cpp index cc5036846e..53953a7cca 100644 --- a/src/libslic3r/GCode/GCodeProcessor.cpp +++ b/src/libslic3r/GCode/GCodeProcessor.cpp @@ -310,6 +310,7 @@ void GCodeProcessor::TimeMachine::reset() g1_times_cache = std::vector(); first_layer_time = 0.0f; prepare_time = 0.0f; + m_additional_time_buffer.clear(); } static void planner_forward_pass_kernel(const GCodeProcessor::TimeBlock& prev, GCodeProcessor::TimeBlock& curr) @@ -395,13 +396,48 @@ static void recalculate_trapezoids(std::vector& block } } -void GCodeProcessor::TimeMachine::calculate_time(GCodeProcessorResult& result, PrintEstimatedStatistics::ETimeMode mode, size_t keep_last_n_blocks, float additional_time) +GCodeProcessor::TimeMachine::AdditionalBuffer GCodeProcessor::TimeMachine::merge_adjacent_additional_time_blocks(const AdditionalBuffer& buffer) { - if (!enabled || blocks.size() < 2) + AdditionalBuffer merged; + if (buffer.empty()) + return merged; + + AdditionalBufferBlock current_block = buffer.front(); + for (size_t idx = 1; idx < buffer.size(); ++idx) { + const AdditionalBufferBlock& next_block = buffer[idx]; + if (current_block.first == next_block.first) + current_block.second += next_block.second; + else { + merged.push_back(current_block); + current_block = next_block; + } + } + merged.push_back(current_block); + return merged; +} + +void GCodeProcessor::TimeMachine::calculate_time(GCodeProcessorResult& result, PrintEstimatedStatistics::ETimeMode mode, size_t keep_last_n_blocks, float additional_time, EMoveType target_move_type) +{ + if (!enabled) return; + if (blocks.size() < 2) { + // Not enough blocks to attribute the extra time to yet; buffer it so it is + // applied on a later pass instead of being dropped. + if (additional_time > 0.0f) + m_additional_time_buffer.emplace_back(target_move_type, additional_time); + return; + } assert(keep_last_n_blocks <= blocks.size()); + // Merge any previously buffered extra time with this call's extra time. Each + // entry is applied, in order, to the first block matching its target move type + // (EMoveType::Noop matches any block). + AdditionalBuffer additional_buffer = m_additional_time_buffer; + if (additional_time > 0.0f) + additional_buffer.emplace_back(target_move_type, additional_time); + additional_buffer = merge_adjacent_additional_time_blocks(additional_buffer); + // reverse_pass for (int i = static_cast(blocks.size()) - 1; i > 0; --i) { planner_reverse_pass_kernel(blocks[i - 1], blocks[i]); @@ -415,11 +451,17 @@ void GCodeProcessor::TimeMachine::calculate_time(GCodeProcessorResult& result, P recalculate_trapezoids(blocks); const size_t n_blocks_process = blocks.size() - keep_last_n_blocks; + size_t additional_buffer_idx = 0; for (size_t i = 0; i < n_blocks_process; ++i) { const TimeBlock& block = blocks[i]; float block_time = block.time(); - if (i == 0) - block_time += additional_time; + if (additional_buffer_idx < additional_buffer.size()) { + const EMoveType buf_move_type = additional_buffer[additional_buffer_idx].first; + if (buf_move_type == EMoveType::Noop || buf_move_type == block.move_type) { + block_time += additional_buffer[additional_buffer_idx].second; + ++additional_buffer_idx; + } + } time += double(block_time); result.moves[block.move_id].time[static_cast(mode)] = block_time; @@ -532,6 +574,14 @@ void GCodeProcessor::TimeMachine::calculate_time(GCodeProcessorResult& result, P it_stop_time->elapsed_time = float(time); } + // Carry forward any extra time that found no matching block this pass, so it + // is retried against the blocks of a later pass. + m_additional_time_buffer.clear(); + if (additional_buffer_idx < additional_buffer.size()) + m_additional_time_buffer.insert(m_additional_time_buffer.end(), + additional_buffer.begin() + additional_buffer_idx, + additional_buffer.end()); + if (keep_last_n_blocks) { blocks.erase(blocks.begin(), blocks.begin() + n_blocks_process); @@ -5525,9 +5575,34 @@ void GCodeProcessor::process_filament_change(int id) } m_cp_color.current = m_extruder_colors[next_filament_id]; - simulate_st_synchronize(extra_time); - // store tool change move + + // Store the tool-change move first, then attribute the filament-change delay to + // it rather than to whichever motion block happens to be pending. This keeps the + // delay out of the per-role feature-time distribution (tool-change moves are not + // counted as an extrusion role) while still including it in the total and + // per-layer times. Mirrors BambuStudio's "separate flush time from other types" + // (c54a8333c7) and "unprocessed additional time" (27ef0b1bef) fixes. store_move_vertex(EMoveType::Tool_change); + + // Construct a zero-distance time block for the tool-change move on each enabled + // machine so the synchronize below can land the delay on it. simulate_st_synchronize + // flushes without keeping any blocks, so it is safe to append these directly. + for (size_t i = 0; i < static_cast(PrintEstimatedStatistics::ETimeMode::Count); ++i) { + TimeMachine& machine = m_time_processor.machines[i]; + if (!machine.enabled) + continue; + TimeBlock block; + block.move_id = static_cast(m_result.moves.size()) - 1; + block.move_type = EMoveType::Tool_change; + block.layer_id = std::max(1, m_layer_id); + block.g1_line_id = m_g1_line_id; + block.flags.prepare_stage = m_processing_start_custom_gcode; + block.distance = 0.0f; + block.calculate_trapezoid(); + machine.blocks.push_back(block); + } + + simulate_st_synchronize(extra_time, EMoveType::Tool_change); } void GCodeProcessor::store_move_vertex(EMoveType type, EMovePathType path_type, bool internal_only) @@ -5851,13 +5926,13 @@ void GCodeProcessor::process_filaments(CustomGCode::Type code) } } -void GCodeProcessor::calculate_time(GCodeProcessorResult& result, size_t keep_last_n_blocks, float additional_time) +void GCodeProcessor::calculate_time(GCodeProcessorResult& result, size_t keep_last_n_blocks, float additional_time, EMoveType target_move_type) { // calculate times std::vector actual_speed_moves; for (size_t i = 0; i < static_cast(PrintEstimatedStatistics::ETimeMode::Count); ++i) { TimeMachine& machine = m_time_processor.machines[i]; - machine.calculate_time(m_result, static_cast(i), keep_last_n_blocks, additional_time); + machine.calculate_time(m_result, static_cast(i), keep_last_n_blocks, additional_time, target_move_type); if (static_cast(i) == PrintEstimatedStatistics::ETimeMode::Normal) actual_speed_moves = std::move(machine.actual_speed_moves); } @@ -5911,9 +5986,9 @@ void GCodeProcessor::calculate_time(GCodeProcessorResult& result, size_t keep_la } } -void GCodeProcessor::simulate_st_synchronize(float additional_time) +void GCodeProcessor::simulate_st_synchronize(float additional_time, EMoveType target_move_type) { - calculate_time(m_result, 0, additional_time); + calculate_time(m_result, 0, additional_time, target_move_type); } void GCodeProcessor::update_estimated_times_stats() diff --git a/src/libslic3r/GCode/GCodeProcessor.hpp b/src/libslic3r/GCode/GCodeProcessor.hpp index 546df6fbb2..ad08cc95d4 100644 --- a/src/libslic3r/GCode/GCodeProcessor.hpp +++ b/src/libslic3r/GCode/GCodeProcessor.hpp @@ -560,9 +560,21 @@ class Print; //BBS: prepare stage time before print model, including start gcode time and mostly same with start gcode time float prepare_time; + // Orca: extra time (e.g. filament-change delay) that could not be attributed + // to a matching block on this pass is buffered here and applied on a later + // pass, so it is never dropped or folded into an unrelated move. + using AdditionalBufferBlock = std::pair; + using AdditionalBuffer = std::vector; + AdditionalBuffer m_additional_time_buffer; + void reset(); - void calculate_time(GCodeProcessorResult& result, PrintEstimatedStatistics::ETimeMode mode, size_t keep_last_n_blocks = 0, float additional_time = 0.0f); + // Merge adjacent buffer entries that target the same move type. + static AdditionalBuffer merge_adjacent_additional_time_blocks(const AdditionalBuffer& buffer); + + // additional_time is attributed to the first block matching target_move_type + // (EMoveType::Noop matches any block, i.e. the first processed block). + void calculate_time(GCodeProcessorResult& result, PrintEstimatedStatistics::ETimeMode mode, size_t keep_last_n_blocks = 0, float additional_time = 0.0f, EMoveType target_move_type = EMoveType::Noop); }; struct UsedFilaments // filaments per ColorChange @@ -1115,10 +1127,10 @@ class Print; void process_custom_gcode_time(CustomGCode::Type code); void process_filaments(CustomGCode::Type code); - void calculate_time(GCodeProcessorResult& result, size_t keep_last_n_blocks = 0, float additional_time = 0.0f); + void calculate_time(GCodeProcessorResult& result, size_t keep_last_n_blocks = 0, float additional_time = 0.0f, EMoveType target_move_type = EMoveType::Noop); // Simulates firmware st_synchronize() call - void simulate_st_synchronize(float additional_time = 0.0f); + void simulate_st_synchronize(float additional_time = 0.0f, EMoveType target_move_type = EMoveType::Noop); void update_estimated_times_stats(); diff --git a/tests/fff_print/CMakeLists.txt b/tests/fff_print/CMakeLists.txt index 1467c1397f..a91d25609a 100644 --- a/tests/fff_print/CMakeLists.txt +++ b/tests/fff_print/CMakeLists.txt @@ -7,6 +7,7 @@ add_executable(${_TEST_NAME}_tests test_fill.cpp test_flow.cpp test_gcode.cpp + test_gcode_timing.cpp test_gcodewriter.cpp test_model.cpp test_print.cpp diff --git a/tests/fff_print/test_gcode_timing.cpp b/tests/fff_print/test_gcode_timing.cpp new file mode 100644 index 0000000000..a18cc1fd05 --- /dev/null +++ b/tests/fff_print/test_gcode_timing.cpp @@ -0,0 +1,185 @@ +#include + +#include "libslic3r/libslic3r.h" +#include "libslic3r/GCode/GCodeProcessor.hpp" +#include "libslic3r/PrintConfig.hpp" + +#include "test_utils.hpp" + +#include +#include + +using namespace Slic3r; +using Catch::Matchers::WithinAbs; + +// Regression coverage for filament/tool-change time being folded into the first +// pending motion block (an extrusion move) instead of the tool-change move, and +// for that delay being dropped entirely when too few motion blocks precede the +// change. See BambuStudio "seperate flush time from other types" (c54a8333c7) +// and the follow-up "unprocessed addtional time" fix (27ef0b1bef). +namespace { + +constexpr size_t NORMAL = static_cast(PrintEstimatedStatistics::ETimeMode::Normal); + +FullPrintConfig make_config(double load_time, double unload_time, double tool_change_time) +{ + FullPrintConfig config; // default-initialized with the built-in defaults + config.gcode_flavor.value = gcfMarlinFirmware; + // Two filaments, both assigned to the same (single) extruder, so a T1 after + // T0 is a same-extruder filament swap that costs unload + load time. + config.filament_diameter.values = {1.75, 1.75}; + config.filament_map.values = {1, 1}; + config.machine_load_filament_time.value = load_time; + config.machine_unload_filament_time.value = unload_time; + config.machine_tool_change_time.value = tool_change_time; + return config; +} + +void run_processor(GCodeProcessor& proc, const FullPrintConfig& config, const char* gcode) +{ + // reserved_tag() selects between two tag tables based on this shared static, and + // other tests in the binary mutate it -- pin it so our "; FEATURE:" role tags are + // parsed deterministically regardless of test execution order. + GCodeProcessor::s_IsBBLPrinter = true; + ScopedTemporaryFile temp(".gcode"); + { + std::ofstream os(temp.string()); + os << gcode; + } + proc.apply_config(config); + // No producer marker in the gcode, so process_file keeps our applied config. + proc.process_file(temp.string()); +} + +// Estimated time per extrusion role, grouped exactly the way libvgcode builds the +// feature-type legend: sum MoveVertex.time over EMoveType::Extrude moves keyed by +// extrusion_role (see ViewerImpl.cpp:1017 -- only Extrude moves are counted). +std::map role_times(const GCodeProcessorResult& r) +{ + std::map m; + for (const auto& mv : r.moves) + if (mv.type == EMoveType::Extrude) + m[mv.extrusion_role] += mv.time[NORMAL]; + return m; +} + +// Sum of estimated time attributed to tool-change moves. +double sum_tool_change_time(const GCodeProcessorResult& r) +{ + double t = 0.0; + for (const auto& mv : r.moves) + if (mv.type == EMoveType::Tool_change) + t += mv.time[NORMAL]; + return t; +} + +// Total filament-change delay, accumulated independently of the timing machinery. +double filament_change_delay(const GCodeProcessorResult& r) +{ + const auto& s = r.print_statistics; + return s.total_filament_load_time + s.total_filament_unload_time + s.total_tool_change_time; +} + +} // namespace + +TEST_CASE("Filament-change time is attributed to tool-change moves, not extrusion roles", "[GCodeTiming]") +{ + // Relative extrusion (M83) so every "E5" is a real 5mm extrusion move rather + // than a zero-delta travel. Two real travels precede T0 so its delay is flushed + // cleanly. The extrusions after T0 span several roles (Outer wall, Sparse infill, + // Inner wall); the first pending block at T1 is an "Outer wall" move, so the + // buggy code folds the T1 delay into that role. The per-role check below verifies + // EVERY role stays clean, not just one, and catches any role-to-role misattribution. + const char* gcode = + "M83\n" + "; FEATURE: Outer wall\n" + "G1 X10 Y10 Z0.2 F600\n" + "G1 X0 Y0 F6000\n" + "T0\n" + "; FEATURE: Outer wall\n" + "G1 X50 Y0 E5 F1800\n" + "G1 X50 Y50 E5\n" + "; FEATURE: Sparse infill\n" + "G1 X0 Y50 E5\n" + "G1 X0 Y0 E5\n" + "T1\n" + "; FEATURE: Inner wall\n" + "G1 X50 Y0 E5\n" + "G1 X50 Y50 E5\n"; + + GCodeProcessor proc_zero; + run_processor(proc_zero, make_config(0.0, 0.0, 0.0), gcode); + const GCodeProcessorResult& r_zero = proc_zero.get_result(); + + const double load = 10.0; + const double unload = 5.0; + GCodeProcessor proc_delay; + run_processor(proc_delay, make_config(load, unload, 0.0), gcode); + const GCodeProcessorResult& r_delay = proc_delay.get_result(); + + const double delay = filament_change_delay(r_delay); + + // Preconditions: the filament changes were charged, and cost nothing in the + // zero-time baseline. + REQUIRE(delay > 0.0); + REQUIRE_THAT(filament_change_delay(r_zero), WithinAbs(0.0, 1e-9)); + + // The delay must not inflate the time of ANY extrusion role. Compare the full + // per-role breakdown (exactly how the feature-type legend is built) between the + // zero-delay and delayed runs -- every role must match to within tolerance. + const auto roles_zero = role_times(r_zero); + const auto roles_delay = role_times(r_delay); + // Guard: the gcode must genuinely exercise multiple distinct roles (Outer wall, + // Sparse infill, Inner wall), otherwise this check would silently cover only one. + REQUIRE(roles_zero.size() >= 3); + REQUIRE(roles_zero.size() == roles_delay.size()); + for (const auto& [role, zero_time] : roles_zero) { + INFO("extrusion role index = " << static_cast(role)); + REQUIRE(roles_delay.count(role) == 1); + REQUIRE_THAT(roles_delay.at(role), WithinAbs(zero_time, 1e-2)); + } + + // The delay must instead land on the tool-change moves, so per-move consumers + // (layer-time view, layer slider) stay consistent. + REQUIRE_THAT(sum_tool_change_time(r_delay), WithinAbs(delay, 1e-2)); + + // Both tool changes occur on layer 1, so the delay must also be reflected in + // the first-layer time. + const double first_layer_delta = proc_delay.get_first_layer_time(PrintEstimatedStatistics::ETimeMode::Normal) + - proc_zero.get_first_layer_time(PrintEstimatedStatistics::ETimeMode::Normal); + REQUIRE_THAT(first_layer_delta, WithinAbs(delay, 1e-2)); +} + +TEST_CASE("Filament-change time is not dropped when few motion blocks precede the change", "[GCodeTiming]") +{ + // Only a single motion block precedes T0, so the buggy code's "fewer than two + // pending blocks" early-out discards that filament-change delay entirely, + // making the total print time inconsistent with the reported statistics. + const char* gcode = + "; FEATURE: Outer wall\n" + "G1 X10 Y10 Z0.2 F600\n" + "T0\n" + "G1 X50 Y0 E5 F1800\n" + "G1 X50 Y50 E5\n" + "T1\n" + "G1 X0 Y50 E5\n" + "G1 X0 Y0 E5\n"; + + GCodeProcessor proc_zero; + run_processor(proc_zero, make_config(0.0, 0.0, 0.0), gcode); + + const double load = 10.0; + const double unload = 5.0; + GCodeProcessor proc_delay; + run_processor(proc_delay, make_config(load, unload, 0.0), gcode); + const GCodeProcessorResult& r_delay = proc_delay.get_result(); + + const double delay = filament_change_delay(r_delay); + REQUIRE(delay > 0.0); + + // Every second of reported filament-change delay must be present in the total + // estimated print time; none may be silently dropped. + const double total_delta = proc_delay.get_time(PrintEstimatedStatistics::ETimeMode::Normal) + - proc_zero.get_time(PrintEstimatedStatistics::ETimeMode::Normal); + REQUIRE_THAT(total_delta, WithinAbs(delay, 1e-2)); +}