From b638d10c0d325c3f53e5523b816b18f12dcd98fe Mon Sep 17 00:00:00 2001 From: 85vmh Date: Sat, 12 Sep 2026 15:54:05 +0200 Subject: [PATCH] Expose the interpreter subroutine call stack in task status Task status carried only callLevel, so a GUI could tell that a subroutine was running but not which one, nor where it was called from. Worse, callLevel was sampled from the live interpreter at interp_list dequeue time, so it described wherever the interpreter had read ahead to rather than the move the machine was actually executing -- the two are decoupled by up to [TASK]INTERP_MAX_LEN queued canon commands plus the motion queue. Rather than reading the interpreter's current state, recover the stack that was active when the executing move was interpreted: - The interpreter records every subroutine call as a call_stack_node holding the call site (filename, line), the subroutine name, and the id of its caller -- a linked chain, so a whole stack is addressable by one integer. Nodes live in a fixed ring of INTERP_CALL_STACK_NODES (16384, ~512kB of non-realtime memory) and each stores its own id, so a node whose slot has been reused is detected on lookup instead of being reported as some unrelated call. enter_context() pushes, leave_context() pops, unwind_call() resets to the root. - write_state_tag() stamps the current node id into every block's StateTag as GM_FIELD_CALL_STACK_ID. It rides through segment merging and TP blending like the other tag fields. - InterpBase gains resolve_call_stack_depth(node_id) and resolve_call_stack_frame(node_id, level, ...), with defaults that report an empty stack; Interp implements them by walking the node chain. A chain that cannot be resolved in full reports depth 0 rather than a partial stack against a truncated depth. - emcTaskUpdate() resolves the tag of the move motion is executing and fills EMC_TASK_STAT::callStack[], deriving callLevel from the same id so depth and frames always describe one point in the program. The stack is cleared once the interpreter goes idle. emcTaskExecute() no longer writes callLevel. EMC_TASK_STAT grows EmcCallFrame {filename, subname, line} and callStack[] of up to EMC_MAX_CALL_STACK frames. Frame[i] reads "at line L of file F we called subroutine S", i == 0 being the call made from the main program. That growth pushes EMC_STAT past the 10240-byte emcStatus NML buffer, which would make NML::write() silently drop status and leave LinuxCNC looking hung to every GUI, with nothing failing at build time. configs/common/{client,server}.nml go to 20480, and emcops.cc gains a static_assert on sizeof(EMC_STAT) so the build trips before that can happen again. Exposed to Python as stat.call_stack, a tuple of dicts with 'filename', 'subname' and 'line' keys. tests/interp/call-stack runs a program whose subroutines sit in separate files and checks that stat.call_stack still names outer/inner while the machine is cutting inside them -- the point at which the live interpreter has already read to EOF, and the case the old callLevel got wrong. Two bounds fixes found along the way, both reachable before this change: enter_context() incremented call_level before testing it against INTERP_SUB_ROUTINE_LEVELS, leaving it one past the end of sub_context[] on the error path, which unwind_call() then indexed; and interpmodule's set_call_level setter accepted any int from Python into the same index. tests/motion/heading gains an assertion that iscircle agrees with the motion type, as a regression guard on the StateTag flag bits. Co-Authored-By: Claude Opus 5 (1M context) --- configs/common/client.nml | 2 +- configs/common/server.nml | 2 +- src/emc/nml_intf/emc.cc | 5 + src/emc/nml_intf/emc_nml.hh | 22 ++- src/emc/nml_intf/emcops.cc | 10 ++ src/emc/nml_intf/state_tag.h | 5 + src/emc/rs274ngc/interp_base.hh | 14 ++ src/emc/rs274ngc/interp_internal.cc | 89 +++++++++++ src/emc/rs274ngc/interp_internal.hh | 24 +++ src/emc/rs274ngc/interp_o_word.cc | 20 ++- src/emc/rs274ngc/interp_setup.cc | 3 + src/emc/rs274ngc/interp_write.cc | 4 + src/emc/rs274ngc/interpmodule.cc | 4 + src/emc/rs274ngc/rs274ngc_interp.hh | 9 ++ src/emc/rs274ngc/rs274ngc_pre.cc | 5 + src/emc/task/emctask.cc | 40 +++++ src/emc/task/emctaskmain.cc | 4 +- src/emc/usr_intf/axis/extensions/emcmodule.cc | 35 +++++ tests/interp/call-stack/expected | 1 + tests/interp/call-stack/subs/inner.ngc | 4 + tests/interp/call-stack/subs/outer.ngc | 5 + tests/interp/call-stack/test-ui.py | 140 ++++++++++++++++++ tests/interp/call-stack/test.ini | 96 ++++++++++++ tests/interp/call-stack/test.ngc | 7 + tests/interp/call-stack/test.sh | 4 + tests/motion/heading/test-ui.py | 12 ++ 26 files changed, 560 insertions(+), 6 deletions(-) create mode 100644 tests/interp/call-stack/expected create mode 100644 tests/interp/call-stack/subs/inner.ngc create mode 100644 tests/interp/call-stack/subs/outer.ngc create mode 100755 tests/interp/call-stack/test-ui.py create mode 100644 tests/interp/call-stack/test.ini create mode 100644 tests/interp/call-stack/test.ngc create mode 100755 tests/interp/call-stack/test.sh diff --git a/configs/common/client.nml b/configs/common/client.nml index 50610c952d6..8ee628e6d02 100644 --- a/configs/common/client.nml +++ b/configs/common/client.nml @@ -13,7 +13,7 @@ # Top-level buffers to EMC B emcCommand SHMEM 192.168.0.4 8192 0 0 1 16 1001 TCP=5005 xdr queue confirm_write serial -B emcStatus SHMEM 192.168.0.4 10240 0 0 2 16 1002 TCP=5005 xdr +B emcStatus SHMEM 192.168.0.4 20480 0 0 2 16 1002 TCP=5005 xdr B emcError SHMEM 192.168.0.4 8192 0 0 3 16 1003 TCP=5005 xdr queue # Processes diff --git a/configs/common/server.nml b/configs/common/server.nml index 7a4c0e00cf4..eac3c7bb438 100644 --- a/configs/common/server.nml +++ b/configs/common/server.nml @@ -10,7 +10,7 @@ # Top-level buffers to EMC B emcCommand SHMEM localhost 8192 0 0 1 16 1001 TCP=5005 xdr queue confirm_write serial -B emcStatus SHMEM localhost 10240 0 0 2 16 1002 TCP=5005 xdr +B emcStatus SHMEM localhost 20480 0 0 2 16 1002 TCP=5005 xdr B emcError SHMEM localhost 8192 0 0 3 16 1003 TCP=5005 xdr queue # Processes diff --git a/src/emc/nml_intf/emc.cc b/src/emc/nml_intf/emc.cc index 3eb7360bdd3..7b79827fab9 100644 --- a/src/emc/nml_intf/emc.cc +++ b/src/emc/nml_intf/emc.cc @@ -1381,6 +1381,11 @@ void EMC_TASK_STAT::update(CMS * cms) cms->update((int *) &execState, 1); cms->update((int *) &interpState, 1); cms->update(callLevel); + for (int i = 0; i < EMC_MAX_CALL_STACK; i++) { + cms->update(callStack[i].filename, sizeof(callStack[i].filename)); + cms->update(callStack[i].subname, sizeof(callStack[i].subname)); + cms->update(callStack[i].line); + } cms->update(motionLine); cms->update(currentLine); cms->update(readLine); diff --git a/src/emc/nml_intf/emc_nml.hh b/src/emc/nml_intf/emc_nml.hh index 5cede52b09f..3c548af7d26 100644 --- a/src/emc/nml_intf/emc_nml.hh +++ b/src/emc/nml_intf/emc_nml.hh @@ -1441,6 +1441,21 @@ class EMC_TASK_STAT_MSG:public RCS_STAT_MSG { uint64_t taskbeat; // milltask's main loop heartbeat counter }; +// Keep >= INTERP_SUB_ROUTINE_LEVELS (interp_internal.hh); asserted in emctask.cc, +// which is able to include both headers. +#define EMC_MAX_CALL_STACK 10 + +// One frame of the subroutine call stack: "at line of we +// called subroutine ". Sizes are kept tight because EMC_TASK_STAT is +// copied through the emcStatus NML buffer on every cycle - see the static_assert +// on sizeof(EMC_STAT) in emcops.cc. +struct EmcCallFrame { + char filename[LINELEN]; // file containing the call site; same PATH_MAX -> + // LINELEN truncation as EMC_TASK_STAT::file + char subname[64]; // O-word subroutine name that was called + int line; // line number of the call site +}; + class EMC_TASK_STAT:public EMC_TASK_STAT_MSG { public: EMC_TASK_STAT(); @@ -1455,7 +1470,12 @@ class EMC_TASK_STAT:public EMC_TASK_STAT_MSG { EMC_TASK_EXEC execState; // EMC_DONE,WAITING_FOR_MOTION, etc. EMC_TASK_INTERP interpState; // EMC_IDLE,READING,PAUSED,WAITING - int callLevel; // current subroutine level - 0 if not in a subroutine, > 0 otherwise + // Subroutine depth of the move motion is executing -- 0 if not in a + // subroutine. Like motionLine, this lags the interpreter, which reads ahead. + int callLevel; + // The call stack of that same move, callLevel frames deep. callStack[0] is + // the call made from the main program; entries >= callLevel are zeroed. + EmcCallFrame callStack[EMC_MAX_CALL_STACK]; int motionLine; // line motion is executing-- may lag int currentLine; // line currently executing int readLine; // line interpreter has read to diff --git a/src/emc/nml_intf/emcops.cc b/src/emc/nml_intf/emcops.cc index 916e3e3e49a..88f3c9691bf 100644 --- a/src/emc/nml_intf/emcops.cc +++ b/src/emc/nml_intf/emcops.cc @@ -18,6 +18,15 @@ #include "emc.hh" #include "emc_nml.hh" +// EMC_STAT is written to the emcStatus NML buffer every cycle. If it outgrows +// that buffer, NML::write() rejects the message and status silently stops +// updating -- LinuxCNC then looks hung to every GUI, with nothing failing at +// build time. The shipped buffers are 20480 bytes (configs/common/*.nml), less +// CMS header overhead, so trip the build well before that. +static_assert(sizeof(EMC_STAT) < 20000, + "EMC_STAT outgrew the emcStatus NML buffer; " + "see the B emcStatus lines in configs/common/*.nml"); + EMC_AXIS_STAT::EMC_AXIS_STAT() : EMC_AXIS_STAT_MSG(EMC_AXIS_STAT_TYPE, sizeof(EMC_AXIS_STAT)), minPositionLimit(0.0), @@ -122,6 +131,7 @@ EMC_TASK_STAT::EMC_TASK_STAT() execState(EMC_TASK_EXEC::DONE), interpState(EMC_TASK_INTERP::IDLE), callLevel(0), + callStack{}, motionLine(0), currentLine(0), readLine(0), diff --git a/src/emc/nml_intf/state_tag.h b/src/emc/nml_intf/state_tag.h index 91c2049c8ae..3bc2262aa74 100644 --- a/src/emc/nml_intf/state_tag.h +++ b/src/emc/nml_intf/state_tag.h @@ -85,6 +85,11 @@ typedef enum { GM_FIELD_M_MODES_4, GM_FIELD_ORIGIN, GM_FIELD_TOOLCHANGE, + /* Id of the interpreter call-stack node for the block this tag came from. + Lets task recover the full subroutine call stack of the move motion is + executing, long after the interpreter has read past it. 0 means the main + program (empty stack). See Interp::resolve_call_stack_frame(). */ + GM_FIELD_CALL_STACK_ID, GM_FIELD_MAX_FIELDS } StateField; diff --git a/src/emc/rs274ngc/interp_base.hh b/src/emc/rs274ngc/interp_base.hh index 5ac25b3f446..d466ffe5adb 100644 --- a/src/emc/rs274ngc/interp_base.hh +++ b/src/emc/rs274ngc/interp_base.hh @@ -49,6 +49,20 @@ public: virtual int reset() = 0; virtual int line() = 0; virtual int call_level() = 0; + + // Recover the subroutine call stack that was active when a block was + // interpreted, identified by the call-stack node id its StateTag carries. + // This lets task report the call stack of the move motion is *executing*, + // which lags the interpreter by the whole read-ahead queue. + // resolve_call_stack_depth() returns the depth (0 == main program), or 0 if + // the id is no longer known. resolve_call_stack_frame() fills in one frame + // and returns 0 on success, -1 if the id or level cannot be resolved. + // Interpreters that do not track subroutine calls keep these defaults. + virtual int resolve_call_stack_depth(int /*node_id*/) { return 0; } + virtual int resolve_call_stack_frame(int /*node_id*/, int /*level*/, + const char ** /*filename*/, + const char ** /*subname*/, + int * /*line*/) { return -1; } virtual char *command(char *buf, size_t buflen) = 0; virtual char *file(char *buf, size_t buflen) = 0; virtual int on_abort(int reason, const char *message) = 0; diff --git a/src/emc/rs274ngc/interp_internal.cc b/src/emc/rs274ngc/interp_internal.cc index ff4ba82cb86..5a2d656dfe5 100644 --- a/src/emc/rs274ngc/interp_internal.cc +++ b/src/emc/rs274ngc/interp_internal.cc @@ -479,6 +479,95 @@ int Interp::set_probe_data(setup_pointer settings) //!< pointer to machine int Interp::call_level(void) { return _setup.call_level; } +// Record a subroutine call made at filename:sequence_number and return the id of +// the new call-stack node. Nodes are kept in a ring and each stores its own id, +// so a node whose slot has since been reused is detected on lookup instead of +// being reported as some unrelated call. +int Interp::push_call_stack_node(setup_pointer settings, const char *filename, + const char *subName, int sequence_number) +{ + if (settings->call_stack_nodes.empty()) + settings->call_stack_nodes.resize(INTERP_CALL_STACK_NODES); + + // id 0 is the reserved root (main program), so it is never handed out + if (settings->call_stack_next_id < 1 || + settings->call_stack_next_id == INT_MAX) + settings->call_stack_next_id = 1; + int id = settings->call_stack_next_id++; + + call_stack_node &node = + settings->call_stack_nodes[id % INTERP_CALL_STACK_NODES]; + node.id = id; + node.parent = settings->call_stack_id; + node.filename = filename; + node.subName = subName; + node.sequence_number = sequence_number; + return id; +} + +// Look up one node by id, or NULL if the ring slot has been reused since. +call_stack_node *Interp::find_call_stack_node(int node_id) +{ + if (node_id <= 0) // 0 is the root: the main program has no frames + return NULL; + if (_setup.call_stack_nodes.empty()) + return NULL; + call_stack_node &node = + _setup.call_stack_nodes[node_id % INTERP_CALL_STACK_NODES]; + if (node.id != node_id) + return NULL; + return &node; +} + +// Walk a node chain to its root, filling frames[] outermost-first. +// Returns the depth, or 0 if the chain cannot be resolved in full: a partially +// resolved stack would be reported against a truncated depth, which is exactly +// the kind of plausible-but-wrong output this mechanism exists to avoid. +int Interp::walk_call_stack(int node_id, call_stack_node **frames, int max_frames) +{ + call_stack_node *chain[INTERP_SUB_ROUTINE_LEVELS]; + int depth = 0; + + for (int id = node_id; id > 0; ) { + if (depth >= INTERP_SUB_ROUTINE_LEVELS) + return 0; // longer than the interpreter can nest: not a valid chain + call_stack_node *node = find_call_stack_node(id); + if (node == NULL) + return 0; // slot reused, so this id is older than the ring + chain[depth++] = node; + id = node->parent; + } + + // chain[] came out innermost-first; callers want outermost-first + for (int i = 0; i < depth && i < max_frames; i++) + frames[i] = chain[depth - 1 - i]; + return depth; +} + +int Interp::resolve_call_stack_depth(int node_id) +{ + call_stack_node *frames[INTERP_SUB_ROUTINE_LEVELS]; + return walk_call_stack(node_id, frames, INTERP_SUB_ROUTINE_LEVELS); +} + +// Frame[i] records "at line L of file F we called subroutine S", with i == 0 +// being the call made from the main program. +int Interp::resolve_call_stack_frame(int node_id, int level, const char **filename, + const char **subname, int *line) +{ + call_stack_node *frames[INTERP_SUB_ROUTINE_LEVELS]; + int depth = walk_call_stack(node_id, frames, INTERP_SUB_ROUTINE_LEVELS); + + if (level < 0 || level >= depth) + return -1; + + const call_stack_node *node = frames[level]; + if (filename) *filename = node->filename ? node->filename : ""; + if (subname) *subname = node->subName ? node->subName : ""; + if (line) *line = node->sequence_number; + return 0; +} + std::string toString(GCodes g) { char buf[15]={}; diff --git a/src/emc/rs274ngc/interp_internal.hh b/src/emc/rs274ngc/interp_internal.hh index 6cfefb01228..4eb28bf6db2 100644 --- a/src/emc/rs274ngc/interp_internal.hh +++ b/src/emc/rs274ngc/interp_internal.hh @@ -20,6 +20,7 @@ #include #include #include +#include #include #include "nml_intf/canon.hh" #include @@ -622,6 +623,26 @@ struct context_struct { #define CONTEXT_RESTORE_ON_RETURN 2 // automatically execute M71 on sub return #define REMAP_FRAME 4 // a remap call frame +// Number of call-stack nodes kept for after-the-fact stack resolution. +// The interpreter reads ahead of motion, so a node +// must stay resolvable from the moment it is stamped into a StateTag until the +// corresponding move has finished executing. 16384 nodes covers far more +// subroutine calls than can be in flight through interp_list plus the motion +// queue, and costs ~512kB of ordinary (non-realtime) memory. +#define INTERP_CALL_STACK_NODES 16384 + +// One entry of the interpreter call stack, recorded as a link to its caller so +// that a complete stack can be recovered later from a single integer id. +// Both strings are interned by strstore() and therefore valid for the lifetime +// of the process, so nodes store pointers rather than copies. +struct call_stack_node { + int id; // monotonic id of this node; 0 is the reserved root + int parent; // id of the calling node; 0 at the outermost level + const char *filename; // file containing the call site + const char *subName; // name of the subroutine that was entered + int sequence_number; // line number of the call site +}; + struct offset_struct { int type; const char *filename; // the name of the file @@ -787,6 +808,9 @@ struct setup int value_returned; // the last NGC procedure did/did not return a value int call_level; // current subroutine level context sub_context[INTERP_SUB_ROUTINE_LEVELS]; + int call_stack_id; // id of the current call-stack node, 0 == main + int call_stack_next_id; // next node id to hand out + std::vector call_stack_nodes; // ring of INTERP_CALL_STACK_NODES int call_state; // enum call_states - indicate Py handler reexecution offset_map_type offset_map; // store label x name, file, line diff --git a/src/emc/rs274ngc/interp_o_word.cc b/src/emc/rs274ngc/interp_o_word.cc index b5ae43c9028..828119dc99d 100644 --- a/src/emc/rs274ngc/interp_o_word.cc +++ b/src/emc/rs274ngc/interp_o_word.cc @@ -679,10 +679,12 @@ int Interp::enter_context(setup_pointer settings, block_pointer block) settings->call_level, settings->call_level+1, call_typenames[block->call_type]); - settings->call_level++; - if (settings->call_level >= INTERP_SUB_ROUTINE_LEVELS) { + // check before incrementing: leaving call_level past the end of + // sub_context[] would make unwind_call() index out of bounds + if (settings->call_level + 1 >= INTERP_SUB_ROUTINE_LEVELS) { ERS(NCE_TOO_MANY_SUBROUTINE_LEVELS); } + settings->call_level++; context_pointer frame = &settings->sub_context[settings->call_level]; frame->clear(); // mark frame for finishing remap @@ -693,6 +695,13 @@ int Interp::enter_context(setup_pointer settings, block_pointer block) frame->pystuff.impl->py_return_type = -1; // distinguish call frames: oword,m99,python,remap frame->call_type = block->call_type; + // Record this call so that the stack can be rebuilt later from the node id + // stamped into each block's StateTag. The call site is the caller's current + // position, the same values execute_call() stores in the previous frame. + settings->call_stack_id = push_call_stack_node(settings, + strstore(settings->filename), + block->o_name, + settings->sequence_number); return INTERP_OK; } @@ -712,6 +721,13 @@ int Interp::leave_context(setup_pointer settings, bool restore) leaving_frame->subName = NULL; settings->call_level--; // drop back + // pop the call-stack node pushed by enter_context(). The node itself stays + // in the ring: moves already queued still refer to it by id. + { + call_stack_node *node = find_call_stack_node(settings->call_stack_id); + settings->call_stack_id = node ? node->parent : 0; + } + if (restore && ((leaving_frame->context_status & (CONTEXT_RESTORE_ON_RETURN|CONTEXT_VALID)) == (CONTEXT_RESTORE_ON_RETURN|CONTEXT_VALID))) { diff --git a/src/emc/rs274ngc/interp_setup.cc b/src/emc/rs274ngc/interp_setup.cc index 365e4682d6c..7401f10fbd9 100644 --- a/src/emc/rs274ngc/interp_setup.cc +++ b/src/emc/rs274ngc/interp_setup.cc @@ -157,6 +157,9 @@ setup::setup() : value_returned(0), call_level(0), sub_context{}, + call_stack_id(0), + call_stack_next_id(1), + call_stack_nodes(), call_state(0), adaptive_feed(0), feed_hold(0), diff --git a/src/emc/rs274ngc/interp_write.cc b/src/emc/rs274ngc/interp_write.cc index b6b2e7d53cf..5cc27f3d2b9 100644 --- a/src/emc/rs274ngc/interp_write.cc +++ b/src/emc/rs274ngc/interp_write.cc @@ -220,6 +220,10 @@ int Interp::write_state_tag(block_pointer block, { state.fields[GM_FIELD_LINE_NUMBER] = settings->sequence_number; + // Carried through segment merging and TP blending, so task can report the + // call stack of the move actually being executed rather than the one the + // interpreter has since read ahead to. + state.fields[GM_FIELD_CALL_STACK_ID] = settings->call_stack_id; //FIXME refactor these into setup methods, and maybe put this //whole method in setup struct bool in_remap = (settings->remap_level > 0); diff --git a/src/emc/rs274ngc/interpmodule.cc b/src/emc/rs274ngc/interpmodule.cc index d27624bcb2b..b44125eb365 100644 --- a/src/emc/rs274ngc/interpmodule.cc +++ b/src/emc/rs274ngc/interpmodule.cc @@ -628,6 +628,10 @@ static inline int get_call_level (Interp &interp) { return interp._setup.call_level; } static inline void set_call_level(Interp &interp, int value) { + // sub_context[] is indexed by call_level, so an out-of-range value here + // becomes an out-of-bounds access in leave_context()/unwind_call() + if (value < 0 || value >= INTERP_SUB_ROUTINE_LEVELS) + throw std::out_of_range("call_level out of range"); interp._setup.call_level = value; } static inline int get_current_pocket (Interp &interp) { diff --git a/src/emc/rs274ngc/rs274ngc_interp.hh b/src/emc/rs274ngc/rs274ngc_interp.hh index b39157093e8..5dd82dc6a66 100644 --- a/src/emc/rs274ngc/rs274ngc_interp.hh +++ b/src/emc/rs274ngc/rs274ngc_interp.hh @@ -126,6 +126,9 @@ public: int line() override { return sequence_number(); } int call_level() override; + int resolve_call_stack_depth(int node_id) override; + int resolve_call_stack_frame(int node_id, int level, const char **filename, + const char **subname, int *line) override; char *command(char *buf, size_t len) override { line_text(buf, len); return buf; } @@ -574,6 +577,12 @@ int read_dollar(char *line, int *counter, block_pointer block, // leave current subroutine context int leave_context(setup_pointer settings, bool restore = true); + // call-stack node bookkeeping, backing resolve_call_stack_*() + int push_call_stack_node(setup_pointer settings, const char *filename, + const char *subName, int sequence_number); + call_stack_node *find_call_stack_node(int node_id); + int walk_call_stack(int node_id, call_stack_node **frames, int max_frames); + //int call_fsm(setup_pointer settings, int event); //int execute_pycall(setup_pointer settings, const char *name, int call_phase); int execute_call(setup_pointer settings, context_pointer current_frame, int call_type); diff --git a/src/emc/rs274ngc/rs274ngc_pre.cc b/src/emc/rs274ngc/rs274ngc_pre.cc index c14064dead9..a7d3eac600f 100644 --- a/src/emc/rs274ngc/rs274ngc_pre.cc +++ b/src/emc/rs274ngc/rs274ngc_pre.cc @@ -1219,6 +1219,7 @@ int Interp::init() // initialization stuff for subroutines and control structures _setup.call_level = 0; + _setup.call_stack_id = 0; _setup.defining_sub = 0; _setup.skipping_o = NULL; _setup.offset_map.clear(); @@ -1737,6 +1738,10 @@ int Interp::unwind_call(int status, const char *file, int line, const char *func _setup.sub_name = NULL; } _setup.remap_level = 0; // reset remapping stack + // back at the main program; nodes already in the ring stay resolvable for + // moves still queued or executing + _setup.call_stack_id = 0; + _setup.defining_sub = 0; _setup.skipping_o = NULL; _setup.skipping_to_sub = NULL; diff --git a/src/emc/task/emctask.cc b/src/emc/task/emctask.cc index 67465d507dd..1ffe28f924a 100644 --- a/src/emc/task/emctask.cc +++ b/src/emc/task/emctask.cc @@ -709,6 +709,46 @@ int emcTaskUpdate(EMC_TASK_STAT * stat) char buf[LINELEN]; rtapi_strxcpy(stat->file, interp.file(buf, LINELEN)); + + // Report the subroutine call stack of the move motion is executing, not the + // one the interpreter has read ahead to -- those are decoupled by up to + // [TASK]INTERP_MAX_LEN queued canon commands. The executing move's StateTag + // carries a call-stack node id that the interpreter can still resolve, so + // depth and frames always describe the same point in the program. + { + // The tag keeps the last executed move's value after the queue drains, + // the same way motionLine does, which avoids flicker between moves. But + // once the interpreter is idle the program is over (or was aborted) and + // there is no longer a move to report a stack for. + int node_id = (stat->interpState == EMC_TASK_INTERP::IDLE) + ? 0 + : emcStatus->motion.traj.tag.fields[GM_FIELD_CALL_STACK_ID]; + int lvl = interp.resolve_call_stack_depth(node_id); + if (lvl < 0) lvl = 0; + if (lvl > EMC_MAX_CALL_STACK) lvl = EMC_MAX_CALL_STACK; + + for (int i = 0; i < lvl; i++) { + const char *filename = ""; + const char *subname = ""; + int line = 0; + if (interp.resolve_call_stack_frame(node_id, i, &filename, &subname, + &line) != 0) { + // id aged out of the ring mid-walk: report no stack at all + // rather than a partial one against a full depth + lvl = 0; + break; + } + rtapi_strxcpy(stat->callStack[i].filename, filename); + rtapi_strxcpy(stat->callStack[i].subname, subname); + stat->callStack[i].line = line; + } + + stat->callLevel = lvl; + // clear the tail so stale frames are not left visible to consumers that + // read the struct directly rather than slicing to callLevel + for (int i = lvl; i < EMC_MAX_CALL_STACK; i++) + stat->callStack[i] = EmcCallFrame{}; + } // command set in main // update active G and M codes diff --git a/src/emc/task/emctaskmain.cc b/src/emc/task/emctaskmain.cc index ff0978fe922..19f98e35a7e 100644 --- a/src/emc/task/emctaskmain.cc +++ b/src/emc/task/emctaskmain.cc @@ -2644,7 +2644,9 @@ static int emcTaskExecute(void) if (NULL != emcTaskCommand) { emcTaskEager = 1; emcStatus->task.currentLine = interp_list.get_line_number(); - emcStatus->task.callLevel = emcTaskPlanLevel(); + // callLevel is set by emcTaskUpdate() from the executing + // move's StateTag; the interpreter's live level at dequeue + // time leads motion by the whole read-ahead queue. // and set it for all subsystems which use queued ids emcTrajSetMotionId(emcStatus->task.currentLine); if (emcStatus->motion.traj.queueFull) { diff --git a/src/emc/usr_intf/axis/extensions/emcmodule.cc b/src/emc/usr_intf/axis/extensions/emcmodule.cc index 0c5a5742986..0fcf4da8130 100644 --- a/src/emc/usr_intf/axis/extensions/emcmodule.cc +++ b/src/emc/usr_intf/axis/extensions/emcmodule.cc @@ -1515,6 +1515,33 @@ static PyObject *Stat_tool_table(pyStatChannel * /*s*/, void *) { return res; } +static PyObject *Stat_call_stack(pyStatChannel *s, void *) { + int lvl = s->status.task.callLevel; + if (lvl < 0) lvl = 0; + if (lvl > EMC_MAX_CALL_STACK) lvl = EMC_MAX_CALL_STACK; + // A tuple of callLevel dicts, empty while in the main program. + // frame[i] = "at line L of filename F we called subroutine S", with i == 0 + // being the call made from the main program. + PyObject *res = PyTuple_New(lvl); + if (res == NULL) return NULL; + for (int i = 0; i < lvl; i++) { + const EmcCallFrame &f = s->status.task.callStack[i]; + // Py_BuildValue owns the refcounting; PyDict_SetItemString does not + // steal references, so building the dict by hand leaks one object per + // key on every poll. + PyObject *d = Py_BuildValue("{s:s, s:s, s:i}", + "filename", f.filename, + "subname", f.subname, + "line", f.line); + if (d == NULL) { + Py_DECREF(res); + return NULL; + } + PyTuple_SET_ITEM(res, i, d); + } + return res; +} + static PyObject *Stat_heartbeat(pyStatChannel *s, void *) { #if PY_VERSION_HEX >= 0x030e00f0 // 3.14 return PyLong_FromUInt64(s->status.motion.heartbeat); @@ -1564,6 +1591,14 @@ static PyGetSetDef Stat_getsetlist[] = { (char*)"The tooltable, expressed as a list of tools. Each tool is a dict with the\n" "tool id (tool number), diameter, offsets, etc.", NULL }, + {(char*)"call_stack", (getter)Stat_call_stack, NULL, + (char*)"Subroutine call stack of the move motion is currently executing, as a\n" + "tuple of call_level dicts (empty while in the main program). Index 0 is\n" + "the call made from the main program, the last entry is the innermost\n" + "subroutine. Each dict has 'filename', 'subname' and 'line' keys, giving\n" + "the call site and the name of the subroutine called there.\n" + "Like motion_line, this lags the interpreter, which reads ahead.", NULL + }, {(char*)"heartbeat", (getter)Stat_heartbeat, NULL, (char*)"Motion controller heartbeat counter. Increments every servo cycle.", NULL }, diff --git a/tests/interp/call-stack/expected b/tests/interp/call-stack/expected new file mode 100644 index 00000000000..8c0382aa4aa --- /dev/null +++ b/tests/interp/call-stack/expected @@ -0,0 +1 @@ +Completed successfully diff --git a/tests/interp/call-stack/subs/inner.ngc b/tests/interp/call-stack/subs/inner.ngc new file mode 100644 index 00000000000..22425bbd0c4 --- /dev/null +++ b/tests/interp/call-stack/subs/inner.ngc @@ -0,0 +1,4 @@ +o sub +G1 Y10 F600 +G1 Y0 F600 +o endsub diff --git a/tests/interp/call-stack/subs/outer.ngc b/tests/interp/call-stack/subs/outer.ngc new file mode 100644 index 00000000000..5c74b112c09 --- /dev/null +++ b/tests/interp/call-stack/subs/outer.ngc @@ -0,0 +1,5 @@ +o sub +G1 X20 F600 +o call +G1 X0 F600 +o endsub diff --git a/tests/interp/call-stack/test-ui.py b/tests/interp/call-stack/test-ui.py new file mode 100755 index 00000000000..fbd47cab1cc --- /dev/null +++ b/tests/interp/call-stack/test-ui.py @@ -0,0 +1,140 @@ +#!/usr/bin/env python3 +# +# Checks that stat.call_stack describes the move motion is EXECUTING, not the +# position the interpreter has read ahead to. +# +# The interpreter reads the whole of this short program long before the moves +# finish, so while the machine is still cutting inside o the interpreter +# has already returned to the main program and read to EOF. A call stack taken +# from the live interpreter would be empty (or hold stale frames) at that point; +# one taken from the executing move's StateTag still names outer/inner. + +import linuxcnc +import linuxcnc_util + +import time +import sys +import os + +INTERPTIMEOUT = 5 +GCODETIMEOUT = 120 + +failures = [] + + +def fail(msg): + print("FAIL: {}".format(msg)) + failures.append(msg) + + +ngcfile = None +for i in range(1, len(sys.argv) - 1): + if "-ngc" == sys.argv[i]: + ngcfile = sys.argv[i + 1] + break + +if not ngcfile: + print("Missing NGC-file; run with: test-ui.py -ngc ngcfile.ngc") + sys.exit(1) +if not os.path.exists(ngcfile): + print("NGC-file '{}' does not exist".format(ngcfile)) + sys.exit(1) + +c = linuxcnc.command() +s = linuxcnc.stat() +e = linuxcnc.error_channel() + +l = linuxcnc_util.LinuxCNC(command=c, status=s, error=e) +c.state(linuxcnc.STATE_ESTOP_RESET) +c.state(linuxcnc.STATE_ON) +c.home(-1) +c.wait_complete() +l.wait_for_home([1, 1, 1, 0, 0, 0, 0, 0, 0]) + +c.mode(linuxcnc.MODE_AUTO) +c.program_open(ngcfile) +c.auto(linuxcnc.AUTO_RUN, 1) + +start = time.time() +while time.time() - start < INTERPTIMEOUT: + s.poll() + if s.interp_state != linuxcnc.INTERP_IDLE: + break + time.sleep(0.01) +if s.interp_state == linuxcnc.INTERP_IDLE: + print("Timed out starting interpreter") + sys.exit(1) + +# Collect (call_level, call_stack, read_line, motion_line) while the program runs +saw_depth2 = None +saw_lagging_stack = False +last_shown = None +eof_line = 0 +with open(ngcfile) as f: + eof_line = len(f.readlines()) + +start = time.time() +s.poll() +while s.interp_state != linuxcnc.INTERP_IDLE and time.time() - start < GCODETIMEOUT: + s.poll() + stack = s.call_stack + level = s.call_level + + # Invariant: depth and frames must come from the same point in the program. + if len(stack) != level: + fail("len(call_stack)={} != call_level={}".format(len(stack), level)) + + # print only when the reported stack changes, so the log stays readable + shown = (level, tuple((fr["subname"], os.path.basename(fr["filename"]), + fr["line"]) for fr in stack)) + if shown != last_shown: + print("read_line={:3d} motion_line={:3d} level={} stack={}".format( + s.read_line, s.motion_line, level, list(shown[1]))) + last_shown = shown + + if level == 2 and saw_depth2 is None: + saw_depth2 = [dict(fr) for fr in stack] + + # The interpreter has read to EOF but motion is still inside a subroutine: + # this is exactly the window where a live-interpreter stack would be wrong. + if level > 0 and s.read_line >= eof_line: + saw_lagging_stack = True + + time.sleep(0.01) + +if s.interp_state != linuxcnc.INTERP_IDLE: + print("Timed out running the GCode program") + sys.exit(1) + +# --- checks ----------------------------------------------------------------- + +if saw_depth2 is None: + fail("never observed a 2-deep call stack while executing") +else: + outer, inner = saw_depth2[0], saw_depth2[1] + print("observed depth-2 stack: {}".format(saw_depth2)) + if outer["subname"] != "outer": + fail("frame 0 subname is '{}', expected 'outer'".format(outer["subname"])) + if inner["subname"] != "inner": + fail("frame 1 subname is '{}', expected 'inner'".format(inner["subname"])) + if os.path.basename(outer["filename"]) != "test.ngc": + fail("frame 0 filename is '{}', expected test.ngc".format(outer["filename"])) + if os.path.basename(inner["filename"]) != "outer.ngc": + fail("frame 1 filename is '{}', expected outer.ngc".format(inner["filename"])) + +if not saw_lagging_stack: + fail("call stack never lagged the interpreter; it is not reporting the " + "executing move") + +s.poll() +if s.call_level != 0: + fail("call_level is {} after program end, expected 0".format(s.call_level)) +if len(s.call_stack) != 0: + fail("call_stack is {} after program end, expected empty".format(s.call_stack)) + +if failures: + print("{} check(s) failed".format(len(failures))) + sys.exit(1) + +print("call-stack checks passed") +sys.exit(0) diff --git a/tests/interp/call-stack/test.ini b/tests/interp/call-stack/test.ini new file mode 100644 index 00000000000..a665e36bc1c --- /dev/null +++ b/tests/interp/call-stack/test.ini @@ -0,0 +1,96 @@ +[EMC] +DEBUG = 0 +VERSION = 1.1 + +[DISPLAY] +DISPLAY = ./test-ui.py -ngc ./test.ngc + +[TASK] +TASK = milltask +CYCLE_TIME = 0.001 + +[RS274NGC] +PARAMETER_FILE = sim.var +SUBROUTINE_PATH = ./subs + +[EMCMOT] +EMCMOT = motmod +BASE_PERIOD = 0 +SERVO_PERIOD = 1000000 + +[HAL] +HALFILE = LIB:core_sim.hal + +[TRAJ] +NO_FORCE_HOMING = 1 +AXES = 3 +COORDINATES = X Y Z +HOME = 0 0 0 +LINEAR_UNITS = mm +ANGULAR_UNITS = degree +DEFAULT_LINEAR_VELOCITY = 100 +MAX_LINEAR_VELOCITY = 500 + +[KINS] +KINEMATICS = trivkins +JOINTS = 3 + +[AXIS_X] +MIN_LIMIT = -1000.0 +MAX_LIMIT = 1000.0 +MAX_VELOCITY = 500 +MAX_ACCELERATION = 3000 + +[JOINT_0] +TYPE = LINEAR +HOME = 0.000 +MAX_VELOCITY = 1000 +MAX_ACCELERATION = 3000 +BACKLASH = 0.000 +INPUT_SCALE = 4000 +OUTPUT_SCALE = 1.000 +MIN_LIMIT = -1000.0 +MAX_LIMIT = 1000.0 +FERROR = 0.050 +MIN_FERROR = 0.010 +HOME_SEQUENCE = 0 + +[AXIS_Y] +MIN_LIMIT = -1000.0 +MAX_LIMIT = 1000.0 +MAX_VELOCITY = 500 +MAX_ACCELERATION = 3000 + +[JOINT_1] +TYPE = LINEAR +HOME = 0.000 +MAX_VELOCITY = 500 +MAX_ACCELERATION = 3000 +BACKLASH = 0.000 +INPUT_SCALE = 4000 +OUTPUT_SCALE = 1.000 +MIN_LIMIT = -1000.0 +MAX_LIMIT = 1000.0 +FERROR = 0.050 +MIN_FERROR = 0.010 +HOME_SEQUENCE = 0 + +[AXIS_Z] +MIN_LIMIT = -500.0 +MAX_LIMIT = 500.0 +MAX_VELOCITY = 500 +MAX_ACCELERATION = 3000 + +[JOINT_2] +TYPE = LINEAR +HOME = 0.0 +MAX_VELOCITY = 500 +MAX_ACCELERATION = 3000 +BACKLASH = 0.000 +INPUT_SCALE = 4000 +OUTPUT_SCALE = 1.000 +MIN_LIMIT = -500.0 +MAX_LIMIT = 500.0 +FERROR = 0.050 +MIN_FERROR = 0.010 +HOME_SEQUENCE = 0 diff --git a/tests/interp/call-stack/test.ngc b/tests/interp/call-stack/test.ngc new file mode 100644 index 00000000000..14a7e665507 --- /dev/null +++ b/tests/interp/call-stack/test.ngc @@ -0,0 +1,7 @@ +(Main program. o and o live in separate files under) +(SUBROUTINE_PATH so that each call frame reports a different filename.) +G21 +G0 X0 Y0 Z0 +o call +G0 X0 Y0 Z0 +M2 diff --git a/tests/interp/call-stack/test.sh b/tests/interp/call-stack/test.sh new file mode 100755 index 00000000000..87a3bca3260 --- /dev/null +++ b/tests/interp/call-stack/test.sh @@ -0,0 +1,4 @@ +#!/bin/bash +if linuxcnc -r test.ini; then + echo "Completed successfully" > result +fi diff --git a/tests/motion/heading/test-ui.py b/tests/motion/heading/test-ui.py index 6742371a741..c566048c31a 100755 --- a/tests/motion/heading/test-ui.py +++ b/tests/motion/heading/test-ui.py @@ -120,6 +120,18 @@ def parse_sample(sample): print("{:6d} {}".format(nsamples, sample)) + # iscircle must agree with the motion type. This is a direct regression + # guard on the StateTag flag bits: anything that reuses the bit belonging to + # GM_FLAG_IS_CIRCLE shows up here as iscircle set on a G0/G1, or clear on a + # G2/G3. Exit rather than return False -- the test only compares "Completed + # successfully", so a non-zero exit is what actually fails the run. + if sample[1] in (0, 10, 20, 30): + expect_circle = sample[1] in (20, 30) + if bool(sample[9]) != expect_circle: + print("FAIL iscircle: motion-type {} reported iscircle={}, expected {}" + .format(sample[1], sample[9], expect_circle)) + sys.exit(1) + if None == lastsample or sample[0] != lastsample[0]: return True if sample[1] not in (00,10,20,30):