diff --git a/docs/changes/newsfragments/8684.new b/docs/changes/newsfragments/8684.new new file mode 100644 index 000000000000..f0b859208858 --- /dev/null +++ b/docs/changes/newsfragments/8684.new @@ -0,0 +1,8 @@ +Added recording of parameter access: inside a ``with qcodes.parameters.record_parameter_accesses() as accesses:`` block, +every ``get`` and ``set`` of a parameter made by the current thread (or asyncio task) is appended to ``accesses`` as a +``qcodes.parameters.ParameterAccess``: the names of the parameter and its instrument, the value and raw value, when the +access started, how long it took and the error it raised, if any. A set that ramps in steps is recorded once per step. +``qcodes.parameters.log_parameter_accesses`` logs the accesses to the ``qcodes.parameters.parameter_access`` logger +instead. Recording only stores data: no user code runs while a parameter is accessed, and a record holds names rather +than the parameter or instrument. This makes it possible to see all instrument communication made by a piece of code +without changing it. diff --git a/docs/examples/Parameters/Recording_Parameter_Access.ipynb b/docs/examples/Parameters/Recording_Parameter_Access.ipynb new file mode 100644 index 000000000000..49c71a8a8806 --- /dev/null +++ b/docs/examples/Parameters/Recording_Parameter_Access.ipynb @@ -0,0 +1,564 @@ +{ + "cells": [ + { + "cell_type": "markdown", + "id": "9d5a1058", + "metadata": {}, + "source": [ + "# Recording parameter access\n", + "\n", + "QCoDeS can record every `get` and `set` of every parameter that a piece of code makes. Each access is recorded as a `ParameterAccess`: the names of the parameter and its instrument, the value and raw value, when the access started, how long it took, and the error it raised, if any.\n", + "\n", + "This lets you see what a piece of code did to your instruments without changing the code or the drivers it uses. You can record what a measurement set and read, find out which parameters are queried most often, or keep a log of everything that was set.\n", + "\n", + "Recording only stores what happened:\n", + "\n", + "- Accesses are appended to a plain `list`, or logged to a fixed QCoDeS logger. No code of yours runs while a parameter is accessed, so recording cannot be used to react to an access, for example by setting another parameter.\n", + "- A record holds data only: the names of the parameter and its instrument rather than the objects, and a description of an error rather than the exception.\n", + "- Only accesses made in the context recording was started in are recorded: the current thread, or the current asyncio task." + ] + }, + { + "cell_type": "code", + "execution_count": 1, + "id": "cb341e86", + "metadata": {}, + "outputs": [], + "source": [ + "import logging\n", + "import sys\n", + "import tempfile\n", + "import threading\n", + "from collections import Counter\n", + "from pathlib import Path\n", + "\n", + "from qcodes.dataset import (\n", + " do1d,\n", + " initialise_or_create_database_at,\n", + " load_or_create_experiment,\n", + ")\n", + "from qcodes.instrument_drivers.mock_instruments import (\n", + " DummyInstrument,\n", + " DummyInstrumentWithMeasurement,\n", + ")\n", + "from qcodes.parameters import (\n", + " Parameter,\n", + " ParameterAccess,\n", + " log_parameter_accesses,\n", + " record_parameter_accesses,\n", + ")" + ] + }, + { + "cell_type": "markdown", + "id": "d2d38547", + "metadata": {}, + "source": [ + "We use two mock instruments: a DAC with two channels, and a DMM whose readings depend on the DAC's voltages." + ] + }, + { + "cell_type": "code", + "execution_count": 2, + "id": "361ea797", + "metadata": {}, + "outputs": [], + "source": [ + "dac = DummyInstrument(\"dac\", gates=[\"ch1\", \"ch2\"])\n", + "dmm = DummyInstrumentWithMeasurement(\"dmm\", setter_instr=dac)" + ] + }, + { + "cell_type": "markdown", + "id": "deed3b96", + "metadata": {}, + "source": [ + "## Recording the accesses of a block of code\n", + "\n", + "`record_parameter_accesses` records the accesses made inside a `with` block in a list, in the order they complete." + ] + }, + { + "cell_type": "code", + "execution_count": 3, + "id": "7551cd51", + "metadata": {}, + "outputs": [ + { + "name": "stdout", + "output_type": "stream", + "text": [ + "set dac_ch1: 0.5\n", + "get dmm_v1: 4.3682652935244874\n" + ] + } + ], + "source": [ + "with record_parameter_accesses() as accesses:\n", + " dac.ch1(0.5)\n", + " dmm.v1()\n", + "\n", + "for access in accesses:\n", + " print(f\"{access.kind} {access.parameter_name}: {access.value}\")" + ] + }, + { + "cell_type": "markdown", + "id": "d4c10c17", + "metadata": {}, + "source": [ + "Accesses outside the block are not recorded:" + ] + }, + { + "cell_type": "code", + "execution_count": 4, + "id": "0eb5add7", + "metadata": {}, + "outputs": [ + { + "data": { + "text/plain": [ + "2" + ] + }, + "execution_count": 4, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "dac.ch1(0.7)\n", + "len(accesses)" + ] + }, + { + "cell_type": "markdown", + "id": "4ca4a1bc", + "metadata": {}, + "source": [ + "You can also pass in the list to record in. It has to be a plain `list`: recording only ever appends to it." + ] + }, + { + "cell_type": "code", + "execution_count": 5, + "id": "6f5387c7", + "metadata": {}, + "outputs": [ + { + "data": { + "text/plain": [ + "[0.1, 0.2]" + ] + }, + "execution_count": 5, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "everything: list[ParameterAccess] = []\n", + "with record_parameter_accesses(everything):\n", + " dac.ch2(0.1)\n", + "with record_parameter_accesses(everything):\n", + " dac.ch2(0.2)\n", + "\n", + "[access.value for access in everything]" + ] + }, + { + "cell_type": "markdown", + "id": "ad911579", + "metadata": {}, + "source": [ + "## What a record contains\n", + "\n", + "Each `ParameterAccess` describes one access:\n", + "\n", + "- `parameter_name`: the full name of the parameter.\n", + "- `instrument_name`: the full name of the parameter's root instrument, or `None`.\n", + "- `kind`: `\"get\"` or `\"set\"`.\n", + "- `value`: the value that was read or written.\n", + "- `raw_value`: the value passed to or returned by the instrument, before scaling, offsets or value mappings are applied.\n", + "- `unit`: the parameter's unit.\n", + "- `timestamp`: when the access started, in seconds since the epoch.\n", + "- `duration`: how long the access took, in seconds. Delays configured on the parameter, such as `post_delay`, are not included.\n", + "- `error`: the type and message of the exception the access raised, or `None`.\n", + "\n", + "The difference between `value` and `raw_value` shows what actually reached the instrument. For example, behind a 1:10 voltage divider, setting 2 V on the sample means setting 20 V on the source:" + ] + }, + { + "cell_type": "code", + "execution_count": 6, + "id": "6dbb149b", + "metadata": {}, + "outputs": [ + { + "name": "stdout", + "output_type": "stream", + "text": [ + "value=2.0, raw_value=20.0, error=None\n" + ] + } + ], + "source": [ + "divided = Parameter(\"divided\", unit=\"V\", set_cmd=None, get_cmd=None, scale=10)\n", + "\n", + "with record_parameter_accesses() as set_accesses:\n", + " divided(2.0)\n", + "\n", + "(access,) = set_accesses\n", + "print(f\"value={access.value}, raw_value={access.raw_value}, error={access.error}\")" + ] + }, + { + "cell_type": "markdown", + "id": "b554d90e", + "metadata": {}, + "source": [ + "## Ramped sets are recorded step by step\n", + "\n", + "A parameter with a `step` is set in several steps, each of which is a separate call to the instrument. Every step is recorded:" + ] + }, + { + "cell_type": "code", + "execution_count": 7, + "id": "cacd002a", + "metadata": {}, + "outputs": [ + { + "data": { + "text/plain": [ + "[0.3, 0.4, 0.5]" + ] + }, + "execution_count": 7, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "dac.ch2.step = 0.1\n", + "dac.ch2.inter_delay = 0\n", + "\n", + "with record_parameter_accesses() as ramp:\n", + " dac.ch2(0.5)\n", + "\n", + "[round(access.value, 2) for access in ramp]" + ] + }, + { + "cell_type": "markdown", + "id": "9caa7b47", + "metadata": {}, + "source": [ + "## Failed accesses\n", + "\n", + "An access that raises is recorded too, with a description of the exception in `error`, and the exception then propagates to the caller as usual. A value that fails validation is rejected before the instrument is contacted, so it is not an access and is not recorded." + ] + }, + { + "cell_type": "code", + "execution_count": 8, + "id": "9c54d07b", + "metadata": {}, + "outputs": [ + { + "name": "stdout", + "output_type": "stream", + "text": [ + "The caller still sees the error: the sensor did not answer\n", + "Recorded: get sensor: TimeoutError: the sensor did not answer\n" + ] + } + ], + "source": [ + "def read_unresponsive_sensor() -> float:\n", + " raise TimeoutError(\"the sensor did not answer\")\n", + "\n", + "\n", + "sensor = Parameter(\"sensor\", get_cmd=read_unresponsive_sensor)\n", + "\n", + "with record_parameter_accesses() as failures:\n", + " try:\n", + " sensor()\n", + " except TimeoutError as error:\n", + " print(f\"The caller still sees the error: {error.args[0]}\")\n", + "\n", + "(failure,) = failures\n", + "print(f\"Recorded: {failure.kind} {failure.parameter_name}: {failure.error}\")" + ] + }, + { + "cell_type": "markdown", + "id": "dc58e4a4", + "metadata": {}, + "source": [ + "## What did a measurement do to the instruments?\n", + "\n", + "Recording sees all accesses made in its context, including those QCoDeS makes itself, so it can show what a measurement did. Here we run a 1D sweep and count the accesses per parameter." + ] + }, + { + "cell_type": "code", + "execution_count": 9, + "id": "0aa93da2", + "metadata": {}, + "outputs": [ + { + "name": "stdout", + "output_type": "stream", + "text": [ + "Starting experimental run with id: 1. Using 'qcodes.dataset.do1d'\n" + ] + }, + { + "data": { + "text/plain": [ + "Counter({('dac_ch1', 'set'): 11, ('dmm_v1', 'get'): 11})" + ] + }, + "execution_count": 9, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "initialise_or_create_database_at(Path(tempfile.mkdtemp()) / \"recording.db\")\n", + "load_or_create_experiment(\"recording_parameter_access\", sample_name=\"no sample\")\n", + "\n", + "with record_parameter_accesses() as sweep:\n", + " do1d(dac.ch1, 0, 1, 11, 0.0, dmm.v1, do_plot=False)\n", + "\n", + "Counter((access.parameter_name, access.kind) for access in sweep)" + ] + }, + { + "cell_type": "markdown", + "id": "840b7ca6", + "metadata": {}, + "source": [ + "The sweep set the DAC 11 times and read the DMM 11 times. The accesses are in the order they happened, so we can also follow the sweep point by point:" + ] + }, + { + "cell_type": "code", + "execution_count": 10, + "id": "58960777", + "metadata": {}, + "outputs": [ + { + "name": "stdout", + "output_type": "stream", + "text": [ + "set dac_ch1: 0.000\n", + "get dmm_v1: 4.946\n", + "set dac_ch1: 0.100\n", + "get dmm_v1: 4.862\n", + "set dac_ch1: 0.200\n", + "get dmm_v1: 4.809\n" + ] + } + ], + "source": [ + "for access in sweep[:6]:\n", + " print(f\"{access.kind} {access.parameter_name}: {access.value:.3f}\")" + ] + }, + { + "cell_type": "markdown", + "id": "63c58da9", + "metadata": {}, + "source": [ + "To follow one instrument, filter on the instrument name:" + ] + }, + { + "cell_type": "code", + "execution_count": 11, + "id": "e4072ce8", + "metadata": {}, + "outputs": [ + { + "data": { + "text/plain": [ + "[0.0, 0.1, 0.2, 0.3, 0.4, 0.5, 0.6, 0.7, 0.8, 0.9, 1.0]" + ] + }, + "execution_count": 11, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "dac_sets = [\n", + " access.value\n", + " for access in sweep\n", + " if access.instrument_name == \"dac\" and access.kind == \"set\"\n", + "]\n", + "[round(float(value), 2) for value in dac_sets]" + ] + }, + { + "cell_type": "markdown", + "id": "c5b922e6", + "metadata": {}, + "source": [ + "## Recording is local to a thread\n", + "\n", + "Only accesses made by the thread (or asyncio task) that started recording are recorded. Work in other threads, even while the block runs, is not:" + ] + }, + { + "cell_type": "code", + "execution_count": 12, + "id": "23a74c87", + "metadata": {}, + "outputs": [ + { + "data": { + "text/plain": [ + "[0.3]" + ] + }, + "execution_count": 12, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "with record_parameter_accesses() as here:\n", + " worker = threading.Thread(target=dac.ch1, args=(0.9,))\n", + " worker.start()\n", + " worker.join()\n", + " dac.ch1(0.3)\n", + "\n", + "[access.value for access in here]" + ] + }, + { + "cell_type": "markdown", + "id": "fe51b03d", + "metadata": {}, + "source": [ + "Recordings can be nested. Each one receives every access made while it is active:" + ] + }, + { + "cell_type": "code", + "execution_count": 13, + "id": "13031c57", + "metadata": {}, + "outputs": [ + { + "data": { + "text/plain": [ + "([0.1, 0.2], [0.2])" + ] + }, + "execution_count": 13, + "metadata": {}, + "output_type": "execute_result" + } + ], + "source": [ + "with record_parameter_accesses() as outer:\n", + " dac.ch1(0.1)\n", + " with record_parameter_accesses() as inner:\n", + " dac.ch1(0.2)\n", + "\n", + "[access.value for access in outer], [access.value for access in inner]" + ] + }, + { + "cell_type": "markdown", + "id": "5861ab28", + "metadata": {}, + "source": [ + "## Logging accesses\n", + "\n", + "`log_parameter_accesses` logs the accesses made inside a `with` block to the `qcodes.parameters.parameter_access` logger, at `DEBUG` level unless you choose another. Each log record carries the `ParameterAccess` as its `parameter_access` attribute, so a handler can store it in structured form." + ] + }, + { + "cell_type": "code", + "execution_count": 14, + "id": "63ce152c", + "metadata": {}, + "outputs": [ + { + "name": "stdout", + "output_type": "stream", + "text": [ + "set dac_ch1 = 0.25\n" + ] + }, + { + "name": "stdout", + "output_type": "stream", + "text": [ + "get dmm_v2 = 0.4612975233041446\n" + ] + } + ], + "source": [ + "access_log = logging.getLogger(\"qcodes.parameters.parameter_access\")\n", + "access_log.setLevel(logging.DEBUG)\n", + "access_log.propagate = False\n", + "access_log.addHandler(logging.StreamHandler(sys.stdout))\n", + "\n", + "with log_parameter_accesses():\n", + " dac.ch1(0.25)\n", + " reading = dmm.v2()" + ] + }, + { + "cell_type": "markdown", + "id": "ea5ce8be", + "metadata": {}, + "source": [ + "## Good to know\n", + "\n", + "- Recording adds a little work to every access made while it is active, and none otherwise.\n", + "- Values are recorded as the parameter returned or received them, not copied.\n", + "- An access to a `DelegateParameter` is recorded twice: once for the delegate and once for its source.\n", + "- Only parameters are recorded. Commands that a driver sends directly, for example with `Instrument.write` or `Instrument.ask` in a driver method, are not. Use the instrument's logger (`visa_log` for VISA instruments) to see the communication on the wire." + ] + }, + { + "cell_type": "code", + "execution_count": 15, + "id": "0c6b690d", + "metadata": {}, + "outputs": [], + "source": [ + "dac.close()\n", + "dmm.close()" + ] + } + ], + "metadata": { + "kernelspec": { + "display_name": "Python 3 (ipykernel)", + "language": "python", + "name": "python3" + }, + "language_info": { + "codemirror_mode": { + "name": "ipython", + "version": 3 + }, + "file_extension": ".py", + "mimetype": "text/x-python", + "name": "python", + "nbconvert_exporter": "python", + "pygments_lexer": "ipython3", + "version": "3.12.15" + } + }, + "nbformat": 4, + "nbformat_minor": 5 +} diff --git a/src/qcodes/parameters/__init__.py b/src/qcodes/parameters/__init__.py index 4ff68a69fac7..f92b83ad2aa1 100644 --- a/src/qcodes/parameters/__init__.py +++ b/src/qcodes/parameters/__init__.py @@ -78,6 +78,12 @@ from .multi_channel_instrument_parameter import MultiChannelInstrumentParameter from .multi_parameter import MultiParameter from .parameter import ManualParameter, Parameter, ParameterKWArgs +from .parameter_access import ( + ParameterAccess, + ParameterAccessKind, + log_parameter_accesses, + record_parameter_accesses, +) from .parameter_base import ( ParamDataType, ParameterBase, @@ -112,6 +118,8 @@ "ParamSpecBase", "ParamSpecBaseDict", "Parameter", + "ParameterAccess", + "ParameterAccessKind", "ParameterBase", "ParameterBaseKWArgs", "ParameterKWArgs", @@ -124,4 +132,6 @@ "create_on_off_val_mapping", "expand_setpoints_helper", "invert_val_mapping", + "log_parameter_accesses", + "record_parameter_accesses", ] diff --git a/src/qcodes/parameters/parameter_access.py b/src/qcodes/parameters/parameter_access.py new file mode 100644 index 000000000000..f334d9eeb108 --- /dev/null +++ b/src/qcodes/parameters/parameter_access.py @@ -0,0 +1,253 @@ +""" +Recording of parameter access. + +Every ``get`` and ``set`` of a parameter can be recorded as a +:class:`ParameterAccess`: what was accessed, the value, when and for how long, +and whether it failed. This makes it possible to see what a piece of code did +to the instruments it controls without changing the code or the drivers:: + + >>> from qcodes.parameters import record_parameter_accesses + >>> with record_parameter_accesses() as accesses: + ... dac.ch1(0.1) + ... dmm.v1() + >>> [(access.kind, access.parameter_name) for access in accesses] + [('set', 'dac_ch1'), ('get', 'dmm_v1')] + +Recording is deliberately restricted to storing what happened: + +* Accesses are appended to a plain :class:`list` or logged to a fixed logger + (:func:`log_parameter_accesses`). No user-supplied code runs while a + parameter is accessed, so recording cannot react to an access, for example + by setting another parameter. +* A :class:`ParameterAccess` holds data only: the names of the parameter and + its instrument rather than the objects themselves, and a description of an + error rather than the exception. +* Recording is local to the context it was started in: the current thread, or + the current :mod:`asyncio` task. Accesses made in other threads are not + recorded. Recordings can be nested; each one receives every access made + while it is active. +""" + +from __future__ import annotations + +import logging +from contextlib import contextmanager +from contextvars import ContextVar +from dataclasses import dataclass +from typing import TYPE_CHECKING, Any, Literal + +if TYPE_CHECKING: + from collections.abc import Generator + + from .parameter_base import ParameterBase + +LOG = logging.getLogger(__name__) +"""The logger :func:`log_parameter_accesses` logs accesses to.""" + +ParameterAccessKind = Literal["get", "set"] + + +@dataclass(frozen=True, slots=True) +class ParameterAccess: + """ + A single ``get`` or ``set`` of a parameter. + + A set that ramps the parameter in steps (see :attr:`.ParameterBase.step`) + is recorded once per step, since each step is a separate call to the + instrument. + """ + + parameter_name: str + """The full name of the parameter that was accessed.""" + instrument_name: str | None + """The full name of the parameter's root instrument, if it has one.""" + kind: ParameterAccessKind + """Whether the parameter was read (``"get"``) or written (``"set"``).""" + value: Any + """ + The value that was read, or the value of the step that was written. ``None`` + if a get failed before a value was obtained. The value is recorded as the + parameter returned or received it, not copied. + """ + raw_value: Any + """ + The raw value returned by ``get_raw`` or passed to ``set_raw``. ``None`` if + a get failed before the raw value was obtained. + """ + unit: str + """The unit of the parameter.""" + timestamp: float + """Time the access started, in seconds since the epoch (:func:`time.time`).""" + duration: float + """ + Seconds spent in ``get_raw`` or ``set_raw`` and the conversions around it. + Delays configured on the parameter, such as ``post_delay``, are excluded. + """ + error: str | None = None + """ + The type and message of the exception the access raised, such as + ``"TimeoutError: no reply"``, or ``None`` if it succeeded. + """ + + +class _ListSink: + """Appends accesses to a list.""" + + __slots__ = ("_records",) + + def __init__(self, records: list[ParameterAccess]) -> None: + self._records = records + + def record(self, access: ParameterAccess) -> None: + self._records.append(access) + + +class _LogSink: + """Logs accesses to :data:`LOG`.""" + + __slots__ = ("_level",) + + def __init__(self, level: int) -> None: + self._level = level + + def record(self, access: ParameterAccess) -> None: + if not LOG.isEnabledFor(self._level): + return + if access.error is None: + message, args = ( + "%s %s = %r", + ( + access.kind, + access.parameter_name, + access.value, + ), + ) + else: + message, args = ( + "%s %s failed: %s", + ( + access.kind, + access.parameter_name, + access.error, + ), + ) + LOG.log( + self._level, + message, + *args, + extra={ + "parameter_access": access, + "parameter_name": access.parameter_name, + "instrument_name": access.instrument_name, + }, + ) + + +_Sink = _ListSink | _LogSink + +_active_sinks: ContextVar[tuple[_Sink, ...]] = ContextVar( + "qcodes_parameter_access_sinks", default=() +) + + +@contextmanager +def record_parameter_accesses( + records: list[ParameterAccess] | None = None, +) -> Generator[list[ParameterAccess], None, None]: + """ + Record every parameter access made in the current context in a list. + + Accesses made by the current thread (or asyncio task) while the block runs + are appended to the list, in the order they complete. An access that + raises is recorded too, with its :attr:`ParameterAccess.error`. + + Args: + records: The list to append to. A new list is used if ``None``. + + Yields: + The list the accesses are appended to. + + Raises: + TypeError: If ``records`` is not a :class:`list`. Subclasses are + refused too, so that recording can only ever append. + + """ + if records is None: + records = [] + if type(records) is not list: + raise TypeError( + "Parameter accesses can only be recorded in a list, " + f"not in {type(records).__name__}." + ) + with _sink_active(_ListSink(records)): + yield records + + +@contextmanager +def log_parameter_accesses( + level: int = logging.DEBUG, +) -> Generator[None, None, None]: + """ + Log every parameter access made in the current context. + + Accesses made by the current thread (or asyncio task) while the block runs + are logged to the ``qcodes.parameters.parameter_access`` logger. Each log + record carries the :class:`ParameterAccess` as its ``parameter_access`` + attribute, and the parameter and instrument names as its + ``parameter_name`` and ``instrument_name`` attributes. + + Args: + level: The level to log accesses at. + + """ + with _sink_active(_LogSink(level)): + yield + + +@contextmanager +def _sink_active(sink: _Sink) -> Generator[None, None, None]: + token = _active_sinks.set((*_active_sinks.get(), sink)) + try: + yield + finally: + _active_sinks.reset(token) + + +def _record( + sinks: tuple[_Sink, ...], + parameter: ParameterBase, + kind: ParameterAccessKind, + value: Any, + raw_value: Any, + timestamp: float, + duration: float, + exception: BaseException | None = None, +) -> None: + root = parameter.root_instrument + access = ParameterAccess( + parameter_name=parameter.full_name, + instrument_name=None if root is None else root.full_name, + kind=kind, + value=value, + raw_value=raw_value, + unit=getattr(parameter, "unit", ""), + timestamp=timestamp, + duration=duration, + error=None if exception is None else _describe(exception), + ) + for sink in sinks: + sink.record(access) + + +def _describe(exception: BaseException) -> str: + # The arguments only: the context QCoDeS appends to e.args (e.g. + # "getting dac_ch1") is added after the access is recorded. + return f"{type(exception).__name__}: {exception}" + + +__all__ = [ + "ParameterAccess", + "ParameterAccessKind", + "log_parameter_accesses", + "record_parameter_accesses", +] diff --git a/src/qcodes/parameters/parameter_base.py b/src/qcodes/parameters/parameter_base.py index 5d6342b04aa9..e92940f3f938 100644 --- a/src/qcodes/parameters/parameter_base.py +++ b/src/qcodes/parameters/parameter_base.py @@ -37,6 +37,7 @@ ) from ..utils.types import NumberType +from . import parameter_access as _parameter_access from .cache import _Cache, _CacheProtocol from .named_repr import named_repr from .permissive_range import permissive_range @@ -984,6 +985,12 @@ def get_wrapper(*args: Any, **kwargs: Any) -> ParameterDataTypeVar: raise NotImplementedError( f"Trying to get an abstract parameter: {self.full_name}" ) + sinks = _parameter_access._active_sinks.get() + timestamp = t0 = 0.0 + if sinks: + timestamp = time.time() + t0 = time.perf_counter() + raw_value = None try: # There might be cases where a .get also has args/kwargs raw_value = get_function(*args, **kwargs) @@ -995,12 +1002,33 @@ def get_wrapper(*args: Any, **kwargs: Any) -> ParameterDataTypeVar: self.cache._update_with(value=value, raw_value=raw_value) - return value - except Exception as e: + if sinks: + _parameter_access._record( + sinks, + self, + "get", + value=None, + raw_value=raw_value, + timestamp=timestamp, + duration=time.perf_counter() - t0, + exception=e, + ) e.args = (*e.args, f"getting {self}") raise + if sinks: + _parameter_access._record( + sinks, + self, + "get", + value=value, + raw_value=raw_value, + timestamp=timestamp, + duration=time.perf_counter() - t0, + ) + return value + return get_wrapper def _wrap_set(self, set_function: Callable[..., None]) -> Callable[..., None]: @@ -1041,8 +1069,24 @@ def set_wrapper(value: ParameterDataTypeVar, **kwargs: Any) -> None: # Start timer to measure execution time of set_function t0 = time.perf_counter() - - set_function(raw_val_step, **kwargs) + sinks = _parameter_access._active_sinks.get() + timestamp = time.time() if sinks else 0.0 + + try: + set_function(raw_val_step, **kwargs) + except Exception as e: + if sinks: + _parameter_access._record( + sinks, + self, + "set", + value=val_step, + raw_value=raw_val_step, + timestamp=timestamp, + duration=time.perf_counter() - t0, + exception=e, + ) + raise # Update last set time (used for calculating delays) self._t_last_set = time.perf_counter() @@ -1057,6 +1101,17 @@ def set_wrapper(value: ParameterDataTypeVar, **kwargs: Any) -> None: self._call_on_set_callback(val_step) + if sinks: + _parameter_access._record( + sinks, + self, + "set", + value=val_step, + raw_value=raw_val_step, + timestamp=timestamp, + duration=t_elapsed, + ) + except Exception as e: e.args = (*e.args, f"setting {self} to {value}") raise diff --git a/tests/parameter/test_parameter_access.py b/tests/parameter/test_parameter_access.py new file mode 100644 index 000000000000..80ab64e390d1 --- /dev/null +++ b/tests/parameter/test_parameter_access.py @@ -0,0 +1,296 @@ +from __future__ import annotations + +import asyncio +import logging +import threading +from collections import UserList +from typing import Any + +import pytest + +from qcodes.instrument_drivers.mock_instruments import DummyInstrument +from qcodes.parameters import ( + DelegateParameter, + Parameter, + ParameterAccess, + log_parameter_accesses, + record_parameter_accesses, +) +from qcodes.validators import Numbers + + +def test_records_get_and_set() -> None: + param = Parameter("p", set_cmd=None, get_cmd=None, unit="V", initial_value=0.0) + + with record_parameter_accesses() as accesses: + param(1.5) + assert param() == 1.5 + + assert [(a.parameter_name, a.kind, a.value, a.unit) for a in accesses] == [ + ("p", "set", 1.5, "V"), + ("p", "get", 1.5, "V"), + ] + assert all(a.error is None for a in accesses) + assert all(a.duration >= 0 for a in accesses) + assert all(a.timestamp > 0 for a in accesses) + + +def test_records_names_not_objects() -> None: + instrument = DummyInstrument("recorded_dac", gates=["ch1"]) + try: + with record_parameter_accesses() as accesses: + instrument.ch1(0.5) + finally: + instrument.close() + + (access,) = accesses + assert access.parameter_name == "recorded_dac_ch1" + assert access.instrument_name == "recorded_dac" + # A record is data: it holds no reference to a parameter or instrument. + for field_value in (access.parameter_name, access.instrument_name, access.unit): + assert isinstance(field_value, str) + with pytest.raises(AttributeError): + access.parameter # type: ignore[attr-defined] # noqa: B018 + + +def test_records_are_immutable() -> None: + param = Parameter("p", set_cmd=None) + with record_parameter_accesses() as accesses: + param(1) + + with pytest.raises(AttributeError): + accesses[0].value = 2 # type: ignore[misc] + + +def test_records_raw_values() -> None: + raw = {"value": 0.0} + param = Parameter( + "p", + set_cmd=lambda value: raw.update(value=value), + get_cmd=lambda: raw["value"], + scale=10, + ) + + with record_parameter_accesses() as accesses: + param(2) + assert param() == 2 + + set_access, get_access = accesses + assert (set_access.value, set_access.raw_value) == (2, 20) + assert (get_access.value, get_access.raw_value) == (2, 20) + + +def test_records_every_ramp_step() -> None: + param = Parameter("p", set_cmd=None, get_cmd=None, initial_value=0) + param.step = 1 + + with record_parameter_accesses() as accesses: + param(3) + + assert [(a.kind, a.value) for a in accesses] == [ + ("set", 1), + ("set", 2), + ("set", 3), + ] + + +def test_records_failed_get() -> None: + def fail() -> float: + raise RuntimeError("instrument did not answer") + + param = Parameter("p", get_cmd=fail) + + with ( + record_parameter_accesses() as accesses, + pytest.raises(RuntimeError, match="instrument did not answer"), + ): + param() + + (access,) = accesses + assert access.kind == "get" + assert access.value is None + assert access.raw_value is None + assert access.error == "RuntimeError: instrument did not answer" + + +def test_records_failed_set() -> None: + def fail(value: float) -> None: + raise RuntimeError("instrument refused") + + param = Parameter("p", set_cmd=fail) + + with ( + record_parameter_accesses() as accesses, + pytest.raises(RuntimeError, match="instrument refused"), + ): + param(1) + + (access,) = accesses + assert (access.kind, access.value) == ("set", 1) + assert access.error == "RuntimeError: instrument refused" + + +def test_invalid_value_is_not_an_access() -> None: + param = Parameter("p", set_cmd=None, vals=Numbers(0, 1)) + + with record_parameter_accesses() as accesses, pytest.raises(ValueError): + param(5) + + assert accesses == [] + + +def test_delegate_and_source_are_both_recorded() -> None: + source = Parameter("source", set_cmd=None, get_cmd=None, initial_value=0) + delegate = DelegateParameter("delegate", source=source) + + with record_parameter_accesses() as accesses: + delegate(1) + + assert [(a.parameter_name, a.kind) for a in accesses] == [ + ("source", "set"), + ("delegate", "set"), + ] + + +def test_recording_is_independent_of_on_set_callback() -> None: + callback_values: list[Any] = [] + param = Parameter( + "p", + set_cmd=None, + on_set_callback=lambda _param, value: callback_values.append(value), + ) + + with record_parameter_accesses() as accesses: + param(1) + + assert callback_values == [1] + assert [(a.kind, a.value) for a in accesses] == [("set", 1)] + + +def test_nothing_is_recorded_outside_the_block() -> None: + param = Parameter("p", set_cmd=None, get_cmd=None) + + with record_parameter_accesses() as accesses: + param(1) + param(2) + + assert [a.value for a in accesses] == [1] + + +def test_records_into_a_given_list() -> None: + param = Parameter("p", set_cmd=None) + records: list[ParameterAccess] = [] + + with record_parameter_accesses(records) as accesses: + param(1) + + assert accesses is records + assert [a.value for a in records] == [1] + + +@pytest.mark.parametrize("records", [(), set(), UserList(), type("L", (list,), {})()]) +def test_only_a_plain_list_is_accepted(records: Any) -> None: + with ( + pytest.raises(TypeError, match="only be recorded in a list"), + record_parameter_accesses(records), + ): + pass + + +def test_nested_recordings_both_record() -> None: + param = Parameter("p", set_cmd=None) + + with record_parameter_accesses() as outer: + param(1) + with record_parameter_accesses() as inner: + param(2) + param(3) + + assert [a.value for a in outer] == [1, 2, 3] + assert [a.value for a in inner] == [2] + + +def test_other_threads_are_not_recorded() -> None: + param = Parameter("p", set_cmd=None) + + with record_parameter_accesses() as accesses: + worker = threading.Thread(target=param, args=(1,)) + worker.start() + worker.join() + param(2) + + assert [a.value for a in accesses] == [2] + + +def test_recording_follows_asyncio_tasks() -> None: + param = Parameter("p", set_cmd=None) + + async def set_in_task(value: float) -> None: + param(value) + + async def main() -> list[ParameterAccess]: + with record_parameter_accesses() as recorded: + # A task runs in a copy of the context it was created in. + await asyncio.create_task(set_in_task(1)) + await asyncio.create_task(set_in_task(2)) + return recorded + + assert [a.value for a in asyncio.run(main())] == [1] + + +def test_logs_accesses(caplog: pytest.LogCaptureFixture) -> None: + param = Parameter("logged_p", set_cmd=None, get_cmd=None) + + with caplog.at_level(logging.DEBUG, logger="qcodes.parameters.parameter_access"): + with log_parameter_accesses(): + param(1) + param() + # Not logged: outside the block. + param(2) + + records = [ + r for r in caplog.records if r.name == "qcodes.parameters.parameter_access" + ] + assert [r.getMessage() for r in records] == [ + "set logged_p = 1", + "get logged_p = 1", + ] + access = records[0].parameter_access # type: ignore[attr-defined] + assert isinstance(access, ParameterAccess) + assert records[0].parameter_name == "logged_p" # type: ignore[attr-defined] + + +def test_logs_failed_accesses(caplog: pytest.LogCaptureFixture) -> None: + def fail(value: float) -> None: + raise RuntimeError("instrument refused") + + param = Parameter("logged_p", set_cmd=fail) + + with ( + caplog.at_level(logging.INFO, logger="qcodes.parameters.parameter_access"), + log_parameter_accesses(logging.INFO), + pytest.raises(RuntimeError), + ): + param(1) + + (record,) = [ + r for r in caplog.records if r.name == "qcodes.parameters.parameter_access" + ] + assert record.levelno == logging.INFO + assert ( + record.getMessage() == "set logged_p failed: RuntimeError: instrument refused" + ) + + +def test_recording_and_logging_together(caplog: pytest.LogCaptureFixture) -> None: + param = Parameter("p", set_cmd=None) + + with ( + caplog.at_level(logging.DEBUG, logger="qcodes.parameters.parameter_access"), + record_parameter_accesses() as accesses, + log_parameter_accesses(), + ): + param(1) + + assert [a.value for a in accesses] == [1] + assert any(r.name == "qcodes.parameters.parameter_access" for r in caplog.records)