fix time

src/libslic3r/GCode/GCodeProcessor.cpp

@@ -310,6 +310,7 @@ void GCodeProcessor::TimeMachine::reset()
     g1_times_cache = std::vector<G1LinesCacheItem>();
     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<GCodeProcessor::TimeBlock>& 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<int>(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<size_t>(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<size_t>(PrintEstimatedStatistics::ETimeMode::Count); ++i) {
+        TimeMachine& machine = m_time_processor.machines[i];
+        if (!machine.enabled)
+            continue;
+        TimeBlock block;
+        block.move_id             = static_cast<unsigned int>(m_result.moves.size()) - 1;
+        block.move_type           = EMoveType::Tool_change;
+        block.layer_id            = std::max<unsigned int>(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<TimeMachine::ActualSpeedMove> actual_speed_moves;
     for (size_t i = 0; i < static_cast<size_t>(PrintEstimatedStatistics::ETimeMode::Count); ++i) {
         TimeMachine& machine = m_time_processor.machines[i];
-        machine.calculate_time(m_result, static_cast<PrintEstimatedStatistics::ETimeMode>(i), keep_last_n_blocks, additional_time);
+        machine.calculate_time(m_result, static_cast<PrintEstimatedStatistics::ETimeMode>(i), keep_last_n_blocks, additional_time, target_move_type);
         if (static_cast<PrintEstimatedStatistics::ETimeMode>(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()

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<EMoveType, float>;
+            using AdditionalBuffer      = std::vector<AdditionalBufferBlock>;
+            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();
 

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

tests/fff_print/test_gcode_timing.cpp

@@ -0,0 +1,185 @@
+#include <catch2/catch_all.hpp>
+
+#include "libslic3r/libslic3r.h"
+#include "libslic3r/GCode/GCodeProcessor.hpp"
+#include "libslic3r/PrintConfig.hpp"
+
+#include "test_utils.hpp"
+
+#include <fstream>
+#include <map>
+
+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<size_t>(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<ExtrusionRole, double> role_times(const GCodeProcessorResult& r)
+{
+    std::map<ExtrusionRole, double> 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<int>(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));
+}