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):