Initial implementation of a profiling efun for LDMud

Author: amotzkau

.gitignore

@@ -0,0 +1,4 @@
+build
+dist
+*.egg-info
+setup.cfg

CONTRIBUTORS

@@ -0,0 +1,3 @@
+The following people contributed to the ldmud_tracing package:
+
+- Alexander Motzkau <Gnomi@UNItopia.de>

LICENSE

@@ -0,0 +1,13 @@
+Copyright (c) 2024 by <see contributors list>
+
+Permission to use, copy, modify, and/or distribute this software for any
+purpose with or without fee is hereby granted, provided that the above
+copyright notice and this permission notice appear in all copies.
+
+THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHORS DISCLAIMS ALL WARRANTIES
+WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
+MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHORS BE LIABLE FOR
+ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
+WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
+ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
+OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.

README.md

@@ -0,0 +1,61 @@
+# Python Tracing package for LDMud
+
+Python package to provide tracing information to LPC.
+
+This package provides the following types:
+ * `profile_result`
+
+This package contains the following efuns:
+ * `profile_result profile_call(mixed& result, closure fun, mixed arg, ...)`
+
+## Usage
+
+### Install from the python package index
+
+The efun package can be downloaded from the python package index:
+
+```
+pip3 install --user ldmud-tracing
+```
+
+### Build & install the package yourself
+
+You can build the package yourself.
+
+First clone the repository
+```
+git clone https://github.com/ldmud/python-tracing.git
+```
+
+Install the package
+```
+cd python-tracing
+python3 setup.py install --user
+```
+
+### Automatically load the modules at startup
+
+Also install the [LDMud Python efuns](https://github.com/ldmud/python-efuns) and use its
+[startup.py](https://github.com/ldmud/python-efuns/blob/master/startup.py) as the Python startup script for LDMud.
+It will automatically detect the installed Python efuns and load them.
+
+### Manually load the modules at startup
+
+Add the following lines to your startup script:
+```
+import ldmud_tracing.profile
+
+ldmud_tracing.profile.register()
+```
+
+## Profiling
+
+The `profile_call` efun evaluates the given closure, any extra arguments will
+be passed to the closure. The result will be assigned to the first argument
+which needs to be passed as a reference.
+
+The efun will return a `profile_result` object. This object provides evaluation
+cost and elapsed time information for each executed LPC code line. A complete
+list of functions is available in the efun documentation.
+
+Have fun!

ldmud_tracing/__init__.py

@@ -0,0 +1,188 @@
+import ldmud, sys, collections, dataclasses, time
+
+time_ns = getattr(time, 'time_ns', None)
+if not time_ns:
+    def time_ns():
+        return int(time.time()*1000000)
+
+class profile_result:
+    @dataclasses.dataclass
+    class LineInfo:
+        cost: int = 0            # Eval cost
+        time: int = 0            # Elapsed time in nanoseconds
+        indirect_cost: int = 0   # Eval cost of called functions
+        indirect_time: int = 0   # Elapsed time in nanoseconds of called functions
+
+    @dataclasses.dataclass
+    class FileInfo:
+        cost: int = 0            # Eval cost
+        time: int = 0            # Elapsed time in nanoseconds
+        lines: dict = dataclasses.field(default_factory=lambda: collections.defaultdict(profile_result.LineInfo))
+
+    def __init__(self):
+        self.files = collections.defaultdict(profile_result.FileInfo)
+
+    def add_line_info(self, fname, line, ticks, time):
+        info = self.files[fname]
+        info.cost += ticks
+        info.time += time
+        info.lines[line].cost += ticks
+        info.lines[line].time += time
+
+    def add_line_indirect_info(self, fname, line, ticks, time):
+        info = self.files[fname]
+        info.lines[line].indirect_cost += ticks
+        info.lines[line].indirect_time += time
+
+    def lpc_get_files(self):
+        return ldmud.Array(sorted(self.files.keys()))
+
+    def lpc_get_first_line(self, fname: str):
+        return min(self.files[fname].lines.keys())
+
+    def lpc_get_last_line(self, fname: str):
+        return max(self.files[fname].lines.keys())
+
+    def lpc_get_file_cost(self, fname: str):
+        return self.files[fname].cost
+
+    def lpc_get_file_time(self, fname: str):
+        return self.files[fname].time
+
+    def lpc_get_line_cost(self, fname: str, line: int):
+        return self.files[fname].lines[line].cost
+
+    def lpc_get_line_time(self, fname: str, line: int):
+        return self.files[fname].lines[line].time
+
+    def lpc_get_line_indirect_cost(self, fname: str, line: int):
+        return self.files[fname].lines[line].indirect_cost
+
+    def lpc_get_line_indirect_time(self, fname: str, line: int):
+        return self.files[fname].lines[line].indirect_time
+
+    def lpc_is_empty(self):
+        return not self.files
+
+    def __efun_call_strict__(self, fun: str, *args):
+        return getattr(self, "lpc_" + fun)(*args)
+
+def efun_profile_call(result: ldmud.Lvalue, fun: ldmud.Closure, *args) -> profile_result:
+    """
+    SYNOPSIS
+            profile_result profile_call(mixed& result, closure fun, mixed arg, ...)
+
+    DESCRIPTION
+            Calls <fun> with the given arguments and stores the result in
+            <result>, which must be passed by reference.
+
+            Gathers profiling information that will be returned.
+
+            The resulting object provides the following functions which can be
+            called with call_strict (dot operator):
+
+                string* get_files()
+                    Returns a sorted list of programs that were traced.
+
+                int get_first_line(string filename)
+                    Returns the minimum line number of the given file where
+                    trace information is available.
+
+                int get_last_line(string filename)
+                    Returns the maximum line number of the given file where
+                    trace information is available.
+
+                int get_line_cost(string filename, int linenumber)
+                    Returns the accumulated costs for that line.
+
+                int get_line_indirect_cost(string filename, int linenumber)
+                    Returns those costs for that line, that are incurred in
+                    calls done by this line.
+
+                int get_file_cost(string filename)
+                    Returns the accumulated costs for that file.
+
+                int get_line_time(string filename, int linenumber)
+                    Returns the accumulated durations in nanoseconds for that line.
+
+                int get_line_indirect_time(string filename, int linenumber)
+                    Returns the time for that line, that is used for processing
+                    calls done by this line.
+
+                int get_file_time(string filename)
+                    Returns the accumulated durations in nanoseconds for that file.
+
+                int is_empty()
+                    Returns a value != 0, if there was no information
+                    collected.
+    """
+
+    @dataclasses.dataclass
+    class PreviousLine:
+        fname: str = None
+        line_number: int = None
+        ns: int = None
+        eval_cost: int = None
+
+    if not isinstance(result, ldmud.Lvalue):
+        raise TypeError("Bad arg 1 to profile_call(): expected mixed &.")
+
+    pr = profile_result()
+    stack = [None] * (len(ldmud.call_stack) - 1)
+    last = PreviousLine()
+    last.eval_cost = ldmud.call_stack[-1].eval_cost
+    last.ns = time_ns()
+
+    def hook(ob, instr):
+        nonlocal last, stack
+
+        cur_frame = ldmud.call_stack[-1]
+        cur_fname = cur_frame.file_name
+        cur_ns = time_ns()
+        cur_depth = len(ldmud.call_stack) - 1 # Don't use the current frame.
+
+        if last.fname and last.line_number:
+            pr.add_line_info(last.fname, last.line_number, max(1, cur_frame.eval_cost - last.eval_cost), cur_ns - last.ns)
+            last.ns = cur_ns
+            last.eval_cost = cur_frame.eval_cost
+
+        if instr is None: # Don't do stack cleanup at the end, we will only get the profile_call() call.
+            return
+
+        if cur_fname:
+            last.fname = cur_fname
+            last.line_number = cur_frame.line_number
+
+        while cur_depth > len(stack):
+            new_frame = ldmud.call_stack[len(stack)]
+            if new_frame.type == ldmud.CALL_FRAME_TYPE_LFUN:
+                prev = PreviousLine()
+                prev.fname = new_frame.file_name
+                prev.line_number = new_frame.line_number
+                prev.ns = cur_ns
+                prev.eval_cost = new_frame.eval_cost
+                stack.append(prev)
+            else:
+                stack.append(None)
+
+        while cur_depth < len(stack):
+            prev = stack.pop()
+            if prev is not None and prev.fname and prev.line_number:
+                pr.add_line_indirect_info(prev.fname, prev.line_number, max(1, cur_frame.eval_cost - prev.eval_cost), cur_ns - prev.ns)
+
+    ldmud.register_hook(ldmud.BEFORE_INSTRUCTION, hook)
+    try:
+        result.value = ldmud.efuns.funcall(fun, *args)
+    finally:
+        ldmud.unregister_hook(ldmud.BEFORE_INSTRUCTION, hook)
+    hook(None, None) # Process last instruction
+
+    return pr
+
+
+def register():
+    """
+    Register efuns and types.
+    """
+    ldmud.register_type("profile_result", profile_result)
+    ldmud.register_efun("profile_call", efun_profile_call)

ldmud_tracing/profile.py

@@ -0,0 +1,29 @@
+import setuptools
+
+with open("README.md", "r") as fh:
+    long_description = fh.read()
+
+setuptools.setup(
+    name="ldmud-tracing",
+    version="0.0.1",
+    author="LDMud Team",
+    author_email="ldmud-dev@UNItopia.DE",
+    description="Python tracing package for LDMud",
+    long_description=long_description,
+    long_description_content_type="text/markdown",
+    url="https://github.com/ldmud/python-dbus",
+    packages=setuptools.find_packages(),
+    classifiers=[
+        "Programming Language :: Python :: 3",
+        "Operating System :: OS Independent",
+    ],
+    entry_points={
+        'ldmud_efun': [
+            'profile_call   = ldmud_tracing.profile:efun_profile_call',
+        ],
+        'ldmud_type': [
+            'profile_result = ldmud_tracing.profile:profile_result',
+        ]
+    },
+    zip_safe=False,
+)