.. include:: ../common.txt .. _step_metrics: ************ Step Metrics ************ Step metrics allow a step to record how it performed during a collection so that the information can be collected later by a Dynamic Application. This turns the behavior of a collection into data that can be monitored: request latency, request counts, status-code breakdowns, connection reuse, and any other measurement a step chooses to report. Metrics are recorded by the step that produces them and read back by the :ref:`load_step_metrics ` step, which returns the cached metrics as its result so the remaining steps in the Snippet Argument can transform them into a collection object. The following steps record metrics out-of-the-box: * :ref:`http ` - Latency and status codes, per URL * :ref:`ssh ` - Latency, outcome, and SSH session reuse, per host and command No other included step records metrics. A :ref:`custom Requestor ` or :ref:`Processor ` can record its own with ``record_step_metrics``, in whatever shape it needs. Refer to :ref:`Recording Metrics From a Custom Step ` for more information. .. _step_metrics_lifecycle: How Step Metrics Work ===================== Metrics are recorded as **deltas** during an execution and are written once, at the end of it. Each execution follows the same lifecycle: #. **Record** - The step calls ``record_step_metrics`` with the values for the request it just made, or the work it just did. No I/O is performed. The values are merged into an in-memory buffer for the ``(step name, device, credential, collection window)`` it belongs to. #. **Flush** - When the execution ends, the Snippet Framework writes every buffered entry to the cache. The flush occurs regardless of whether the collection succeeded, so metrics for failed requests are not lost. #. **Read** - A later collection uses the :ref:`load_step_metrics ` step to read the cached entries back for one or more collection windows. Because the values are deltas, the framework merges them twice: once as they are recorded in memory, and again when the buffer is folded into whatever is already cached for that window. Steps executing concurrently on different collector processes therefore accumulate into the same totals. Metrics are cached per collection window. The window is the timestamp of the collection (``collection.app.gmtime``), so a Dynamic Application that runs every five minutes produces one entry every five minutes for each step, device, and credential combination it uses. Each entry is cached under a key built from those values: .. code-block:: none sf_metrics____ An entry is shared rather than owned by the Dynamic Application that wrote it. Every Dynamic Application using the same step against the same device and credential accumulates into the same entry, so a Dynamic Application that reports the metrics sees the traffic of all of them. .. note:: Cached metrics expire two hours after they are written. Read them within the lookback of a regularly scheduled Dynamic Application rather than treating the cache as long-term storage. |PRODUCT_NAME| collection objects are the durable record. .. warning:: Metrics are best-effort observability and never interfere with a collection. If recording, flushing, or reading metrics fails, the failure is logged and the collection continues. This also means a missing entry is normal and must be handled by the Snippet Argument consuming it. .. _step_metrics_alignment: Device Alignment ---------------- Every call to ``record_step_metrics`` records the same values three times: once for the device that performed the collection, once for its parent device, and once for its root device. Duplicate IDs are recorded only once, and a device with no parent or root records only against itself. This allows the metrics to be read back at whichever level is useful. Reading at the root of a device relationship returns the metrics for the whole tree, while reading at the device itself returns only its own. The level is chosen at read time using the ``stat_align`` argument of the :ref:`load_step_metrics ` step: .. list-table:: Alignment Options :widths: 20 80 :header-rows: 1 * - ``stat_align`` - Metrics Returned * - ``self`` - Only the metrics recorded by the aligned device. * - ``parent`` - The metrics for the aligned device's parent, which include the metrics of every child that recorded against it. Falls back to the device itself if it has no parent. * - ``root`` - The metrics for the root of the device relationship, which include every device beneath it. Falls back to the device itself if it has no root. * - not specified - Identical to ``root``. This is the default. Alignment selects the device half of the cache key only. The credential half comes from the credential aligned to the device performing the read, which is why metrics rolled up at a parent or a root are the ones recorded by devices sharing that credential. Use the ``cred_id`` argument to read the metrics recorded under a different credential. .. _step_metrics_enabling: Enabling Step Metrics ===================== Recording is off unless it is asked for, so a step that never opts in costs nothing. Two settings control whether metrics are recorded. Enabling the Feature -------------------- The feature is controlled on the collector by the ``metrics_enabled`` setting in the ``slc`` section of ``silo.conf``. Metrics are enabled unless the setting is explicitly ``false`` or ``0``. When the feature is disabled, ``record_step_metrics`` and the flush become no-ops, and :ref:`load_step_metrics ` returns whatever remains in the cache, which is normally nothing. The setting is read once when a collector process starts, so a change to ``silo.conf`` applies to the processes started after it. A custom step can check the setting with ``step_metrics_enabled`` to avoid computing values that would be discarded: .. code-block:: python from silo.low_code import step_metrics_enabled if step_metrics_enabled(): ... .. _step_metrics_optin: Opting In an Execution ---------------------- With the feature enabled, the :ref:`http ` and :ref:`ssh ` steps still record nothing until an execution asks for it. Recording is requested in one of two places: * **The credential** - The ``Record Step Metrics`` field on the ``Low-code tools: rest v105 Credential`` and the ``Low-code tools: ssh v105 Credential``. This turns recording on for every Dynamic Application aligned to the credential. * **The step argument** - The ``record_metrics`` argument on the step itself, which records a single step without affecting the other Dynamic Applications that share the credential. The credential is the stronger of the two. Whenever the aligned credential defines the field, its value decides in **both** directions, so a credential with the field disabled records nothing even for a step that asks for it. The step argument is only consulted when the aligned credential does not define the field at all, such as an earlier version of the ``Low-code tools`` credentials or a credential type that has no such field. .. list-table:: Resolving the Opt-In :widths: 30 30 40 :header-rows: 1 * - Credential Field - Step Argument - Metrics Recorded * - Enabled - Anything, or not specified - Yes * - Disabled - Anything, or not specified - No * - Not defined by the credential - ``record_metrics: True`` - Yes * - Not defined by the credential - Not specified - No .. important:: Only a boolean ``True``, or the string ``true`` with any case and surrounding whitespace, asks for recording. A value of ``1``, ``yes``, or ``on`` is read as a no. This is stricter than the ``merge_windows`` argument of :ref:`load_step_metrics `, which also accepts ``1``. .. code-block:: yaml :emphasize-lines: 6 low_code: version: 2 steps: - http: uri: /api/account record_metrics: True - json The :ref:`ssh ` step accepts a Snippet Argument that is only the command, which has nowhere to carry the flag. Use the dictionary form of the argument to opt a single ``ssh`` step in: .. code-block:: yaml :emphasize-lines: 6 low_code: version: 2 steps: - ssh: command: lscpu record_metrics: True .. note:: Each recording is logged at the debug level as ``Recorded step metrics: ``, which is the quickest way to confirm an execution opted in. Refer to :ref:`Logging ` for how to enable debug logging. .. _step_metrics_recorded: Metrics Recorded by the Included Steps ====================================== The shape of the recorded metrics is defined by the step that records them. The :ref:`load_step_metrics ` step does not interpret or reshape it. Every duration is a number of **seconds**, never milliseconds, and every ``*_count`` field is a whole number. The :ref:`ssh ` step rounds each reading and each average it derives to six decimal places, while the :ref:`http ` step does not round, so a real ``http`` payload can carry a longer floating-point tail than the shortened examples below. http ---- The :ref:`http ` step records one entry per URL it requested, keyed by the full URL the response came back from, including any query parameters the credential or the step added. A request that never received a response is keyed by the URL it was aimed at instead. Every request the step makes is counted, including the ones that never reached the endpoint. The latency of a request is the elapsed time the underlying HTTP library reports for its response, which covers sending the request and receiving the response headers. It does not include authentication, token retrieval, or the Snippet Framework's own processing, so it measures the endpoint rather than the collection. Compare this with the :ref:`ssh ` step, which measures the whole step. .. note:: A request that the ``retry`` argument repeats is recorded once, against the response it ends on. The status code that triggered the retry, and the time spent on that first attempt, are not part of the metrics. .. note:: The URL is the key, so requests that differ only by a query parameter are recorded separately, and a paginated request records one entry per page it fetched. Where that level of detail is not wanted, aggregate the entries in the Snippet Argument that reads them, such as with a :ref:`jmespath ` expression. .. list-table:: http Metrics :widths: 25 75 :header-rows: 1 * - Metric - Description * - ``url`` - URL the metrics are keyed under, repeated inside the entry so a flattened row still identifies itself. * - ``total_count`` - Requests made against the URL, whether a latency was obtained or not. * - ``measured_count`` - Requests a latency was obtained for. This is the weight behind ``avg_latency`` and differs from ``total_count`` whenever a request failed before a response arrived. * - ``avg_latency`` - Mean seconds per measured request, weighted by ``measured_count``. * - ``min_latency`` - Fastest measured request, in seconds. ``null`` until a request has been measured, rather than a zero that would read as a real value. * - ``max_latency`` - Slowest measured request, in seconds. ``null`` until a request has been measured. * - ``status`` - Breakdown keyed by HTTP status code, or by the name of the raised exception when the request never produced a response. Each entry holds its own ``count``, ``measured_count``, and ``avg_latency``. An entry with no measured request keeps ``avg_latency`` at ``-1``, which marks it as unmeasured rather than instantaneous. .. note:: Status codes are strings in the recorded metrics, since the cache holds JSON and JSON has no integer keys. A ``404`` is read back as ``"404"``. In the following example, two requests to ``/api/account`` succeeded, one request to ``/api/accounts`` returned a ``404``, and one request to ``/api/device`` never reached the endpoint. The unreachable request is counted but not measured, so it leaves ``avg_latency`` at ``0.0`` and the bounds at ``null``: .. code-block:: json { "https://10.2.24.198/api/account?limit=100": { "url": "https://10.2.24.198/api/account?limit=100", "total_count": 2, "measured_count": 2, "avg_latency": 0.028416, "min_latency": 0.026871, "max_latency": 0.029961, "status": { "200": {"count": 2, "measured_count": 2, "avg_latency": 0.028416} } }, "https://10.2.24.198/api/accounts": { "url": "https://10.2.24.198/api/accounts", "total_count": 1, "measured_count": 1, "avg_latency": 0.058312, "min_latency": 0.058312, "max_latency": 0.058312, "status": { "404": {"count": 1, "measured_count": 1, "avg_latency": 0.058312} } }, "https://10.2.24.198/api/device": { "url": "https://10.2.24.198/api/device", "total_count": 1, "measured_count": 0, "avg_latency": 0.0, "min_latency": null, "max_latency": null, "status": { "ConnectionError": {"count": 1, "measured_count": 0, "avg_latency": -1} } } } ssh --- The :ref:`ssh ` step records one entry per command, nested under the host the command was sent to. Step latency is measured from the moment the step is entered, so it covers credential setup, the request itself, and reading the results back. The ``*_exec_time`` and session fields come from the SSH connection pool, which only reports them on the library path; ``session_call_count`` records how many requests they cover. Comparing ``avg_step_latency`` against ``avg_exec_time`` and ``avg_startup_time`` isolates the overhead outside the command itself. .. list-table:: ssh Metrics :widths: 25 75 :header-rows: 1 * - Metric - Description * - ``host`` - Host the metrics are keyed under, repeated for flattened output. * - ``command`` - Command the metrics are keyed under, repeated for flattened output. * - ``call_count`` - Requests the step made for the command. * - ``total_step_latency`` - Total wall-clock seconds the step spent on those requests. * - ``avg_step_latency`` - Average wall-clock seconds per request. * - ``min_step_latency`` - Fastest request, in seconds. * - ``max_step_latency`` - Slowest request, in seconds. * - ``success_count`` - Requests that succeeded, taken from ``status``. * - ``failure_count`` - Requests with any other outcome, however it is named. * - ``status`` - The same step-latency fields per outcome. A clean run is keyed ``success``. A failure reported by the SSH library is keyed by its exception type, such as ``AuthenticationError``, ``UnknownHostError``, or ``Timeout``, so the breakdown shows *how* requests failed. A failure with no exception type is keyed ``failure``, such as a command that ran and exited non-zero or a request that never came back. * - ``session_call_count`` - Requests that reported SSH connection-pool instrumentation. * - ``reused_session_count`` - Requests that reused an already-open pooled SSH session. * - ``new_session_count`` - Requests that had to open a new SSH session. * - ``total_startup_time`` - Total seconds spent opening SSH sessions. * - ``avg_startup_time`` - Average session setup seconds, per instrumented request. * - ``total_exec_time`` - Total seconds the remote host spent running the command. * - ``avg_exec_time`` - Average seconds the remote host spent running the command. * - ``pids`` - Collector process IDs that ran the command. * - ``process_count`` - How many collector processes are in ``pids``. * - ``app_ids`` - Dynamic Application IDs that ran the command. * - ``app_count`` - How many Dynamic Applications are in ``app_ids``. The ``pids`` and ``app_ids`` fields show that a metrics entry is shared. Every Dynamic Application using the same step, device, and credential accumulates into the same entry for the window. .. code-block:: json { "10.1.2.3": { "uptime": { "host": "10.1.2.3", "command": "uptime", "call_count": 3, "total_step_latency": 1.5, "avg_step_latency": 0.5, "min_step_latency": 0.25, "max_step_latency": 0.75, "success_count": 2, "failure_count": 1, "status": { "success": { "call_count": 2, "total_step_latency": 0.75, "avg_step_latency": 0.375, "min_step_latency": 0.25, "max_step_latency": 0.5 }, "AuthenticationError": { "call_count": 1, "total_step_latency": 0.75, "avg_step_latency": 0.75, "min_step_latency": 0.75, "max_step_latency": 0.75 } }, "session_call_count": 3, "reused_session_count": 2, "new_session_count": 1, "total_startup_time": 0.375, "avg_startup_time": 0.125, "total_exec_time": 0.75, "avg_exec_time": 0.25, "pids": [12345, 12346], "process_count": 2, "app_ids": [1006], "app_count": 1 } } } .. _step_metrics_consuming: Consuming Metrics ================= The :ref:`load_step_metrics ` step reads cached metrics back and returns them as the step result, which allows the remaining steps in the Snippet Argument to map the values to a collection object like any other collected data. .. list-table:: load_step_metrics Arguments :widths: 20 12 68 :header-rows: 1 * - Argument - Type - Description * - ``step_name`` - string - **Required.** Step identifier the metrics were recorded under, such as ``http`` or ``ssh``. For a custom step, this is the registered step name. * - ``stat_align`` - string - Optional. ``self``, ``parent``, or ``root``. Which device the cached metrics are attributed to. Refer to :ref:`Device Alignment `. Defaults to ``root``. * - ``cred_id`` - integer - Optional. Credential ID to read metrics for. Defaults to the aligned device's credential. Use this when the metrics were recorded by a Dynamic Application using a different credential than the one reading them. * - ``lookback_minutes`` - integer - Optional. How many minutes back to look for cached entries. Defaults to the frequency of the Dynamic Application performing the read. * - ``times`` - list - Optional. Explicit list of ``gmtime`` timestamps to look up, which overrides ``lookback_minutes``. * - ``merge_windows`` - boolean - Optional. ``true`` or ``1`` merges every window in the lookback into a single set of metrics, which changes the shape of the result. Defaults to ``false``, which returns one entry per window. Refer to :ref:`Merging Every Window `. A malformed argument is a configuration error, so it fails the step rather than being reported as an absence of metrics. ``step_name`` is required and a step without it makes the Snippet Argument invalid, which prevents the collection from running at all. ``cred_id`` and ``lookback_minutes`` must be integers, where a float is truncated so ``90.9`` is read as ``90``, and ``times`` must be a list. Everything after the arguments are resolved is best effort. If the device cannot be resolved, ``stat_align`` is not one of the three supported values, or the cache read fails, the step returns no metrics and logs ``Failed to load step metrics.`` instead of failing the collection. Reading a Window ---------------- The following Snippet Argument records metrics for two endpoints: .. code-block:: yaml low_code: version: 2 steps: - http: uri: /api/account record_metrics: True - http: uri: /api/accounts check_status_code: False record_metrics: True A second Dynamic Application, or another collection object in the same Dynamic Application, reads back everything cached for ``http`` over the last 15 minutes: .. code-block:: yaml low_code: version: 2 steps: - load_step_metrics: step_name: "http" lookback_minutes: 15 The result is keyed by the timestamp of each collection window, with one entry per window that had cached data. The keys are strings, since the cache holds JSON. A window with no cached data, either because it is too old or because it never flushed, is simply absent rather than an empty entry: .. code-block:: json { "1784840100": { "https://10.2.24.198/api/account?limit=100": { "url": "https://10.2.24.198/api/account?limit=100", "total_count": 2, "measured_count": 2, "avg_latency": 0.028416, "min_latency": 0.026871, "max_latency": 0.029961, "status": {"200": {"count": 2, "measured_count": 2, "avg_latency": 0.028416}} } }, "1784840400": { "https://10.2.24.198/api/account?limit=100": { "url": "https://10.2.24.198/api/account?limit=100", "total_count": 2, "measured_count": 2, "avg_latency": 0.030702, "min_latency": 0.030291, "max_latency": 0.031113, "status": {"200": {"count": 2, "measured_count": 2, "avg_latency": 0.030702}} } } } .. important:: The window currently being collected is never returned. Metrics are flushed at the *end* of an execution, so the current window has not been written yet when a collection reads it back. The default lookback stops one window short of the current one, which means :ref:`load_step_metrics ` always reports completed windows. A Dynamic Application that records and reads metrics in the same execution reads the *previous* window's values. When no window in the lookback holds data, the step returns nothing and the steps that follow it have no data to process, so the collection object reports no value for that cycle. This is the expected result for the first run of a Dynamic Application that reads metrics, and it is why those metrics should be mapped to a collection object that tolerates a gap. .. _step_metrics_merging: Merging Every Window -------------------- One entry per window suits a processor that maps each window to its own collection object. To collapse the whole lookback into a single reading, set ``merge_windows``: .. code-block:: yaml :emphasize-lines: 7 low_code: version: 2 steps: - load_step_metrics: step_name: "http" lookback_minutes: 15 merge_windows: true Windows are merged oldest first, using the same handler the source step registered to record them. Counts sum, minimums and maximums span the whole lookback, and averages stay weighted by the number of requests behind them rather than being averaged again. Merging the two windows above gives: .. code-block:: json { "times": [1784840100, 1784840400], "data": { "https://10.2.24.198/api/account?limit=100": { "url": "https://10.2.24.198/api/account?limit=100", "total_count": 4, "measured_count": 4, "avg_latency": 0.029559, "min_latency": 0.026871, "max_latency": 0.031113, "status": {"200": {"count": 4, "measured_count": 4, "avg_latency": 0.029559}} } } } ``times`` lists only the windows that actually contributed, as integers and oldest first, so a window with no cached data is absent from it just as it is absent from the unmerged result. .. note:: Merging depends on the source step being registered in the collection performing the read, since that is where its merge handler comes from. If the step is not registered, no window can be merged and ``data`` comes back empty. This matters for a custom step: the Dynamic Application reading the metrics must include the snippet that registers it. A step that registered no handler of its own is merged by summing, exactly as it was accumulated while recording. Selecting the Device, Credential, and Windows --------------------------------------------- By default the step reads the metrics of the root device in the aligned device's relationship, using the credential aligned to that device. Either can be redirected. A Dynamic Application aligned to a device in a relationship that should report only that device's own metrics sets ``stat_align``: .. code-block:: yaml :emphasize-lines: 6 low_code: version: 2 steps: - load_step_metrics: step_name: "ssh" stat_align: self Metrics are keyed by credential as well as by device, so a Dynamic Application that reads metrics while aligned to a different credential than the one that recorded them sets ``cred_id``: .. code-block:: yaml :emphasize-lines: 6 low_code: version: 2 steps: - load_step_metrics: step_name: "http" cred_id: 42 To read specific collection windows rather than a lookback, list their timestamps with ``times``. Each timestamp is the ``gmtime`` of a collection window, which is a UTC epoch second aligned to the minute. This overrides ``lookback_minutes``: .. code-block:: yaml low_code: version: 2 steps: - load_step_metrics: step_name: "http" times: - 1784840100 - 1784840400 Mapping Metrics to a Collection Object -------------------------------------- Because the metrics are returned as the step result, the usual steps apply to them. The metrics for a single endpoint can be selected directly, using the URL as a JMESPath quoted identifier: .. code-block:: yaml low_code: version: 2 steps: - load_step_metrics: step_name: "http" lookback_minutes: 15 merge_windows: true - jmespath: value: 'data."https://10.2.24.198/api/account?limit=100".avg_latency' To report a value for every endpoint instead, convert the keyed metrics into a list of key-value pairs with :ref:`dict_to_list ` and index the result by the key. Each URL then becomes its own index in the collection object, with its average latency as the value: .. code-block:: yaml low_code: version: 2 steps: - load_step_metrics: step_name: "http" merge_windows: true - jmespath: value: data - dict_to_list - jmespath: index: true value: '[].{_index: key, _value: value.avg_latency}' The ``url``, ``host``, and ``command`` fields are repeated inside each entry for this case, so a flattened row still identifies what it describes. For the :ref:`ssh ` step, whose metrics are nested per host and then per command, run ``dict_to_list`` twice or select a single host first. .. _step_metrics_custom: Recording Metrics From a Custom Step ==================================== A custom step records metrics by calling ``record_step_metrics``. Both a :ref:`Requestor ` and a :ref:`Processor ` can record them, which allows a step to report on the request it made or on the work it did to the result. The values, their names, and their shape are entirely user-defined. A custom step decides for itself when to record. The ``record_metrics`` opt-in described in :ref:`Opting In an Execution ` is a convention of the included steps, not a framework feature, so a custom step records whenever it calls ``record_step_metrics`` and the feature is enabled on the collector. Honoring a ``record_metrics`` step argument of its own keeps a custom step consistent with the included ones. .. autofunction:: silo.low_code.record_step_metrics .. autofunction:: silo.low_code.step_metrics_enabled ``collection`` is one of the :ref:`Standard Parameters `. A custom step can also request ``result_container``, which describes the step that is currently executing and supplies the other two arguments: * ``result_container.did`` - Device being collected, which the metrics are recorded against. * ``result_container.current_step_name`` - Name the step was registered under, which the metrics are recorded beneath. Taking the name from the result container rather than hard-coding it keeps the metrics readable under the right name when a step is registered with a ``name`` override. Using the Default Handler ------------------------- Without a registered handler, the framework merges metrics by summing numeric values. Every value in the dictionary is treated as a delta: an ``int`` or ``float`` is added to whatever has already been recorded for that key, and a non-numeric value is not recorded at all. This is enough for counters. The following custom step records how many requests were made and how many items they returned: .. code-block:: python from silo.low_code import record_step_metrics, register_requestor @register_requestor def bean_counter(step_args, collection, result_container): beans = collect_beans(step_args) record_step_metrics( {"request_count": 1, "bean_count": len(beans)}, collection, result_container.did, result_container.current_step_name, ) return beans After three requests in the same collection window, whether they came from one execution or from several, the cached metrics are the sum of every delta recorded during it: .. code-block:: json {"request_count": 3, "bean_count": 42} Registering a Metrics Handler ----------------------------- Summing is the wrong operation for an average, a minimum, or a maximum. A step that records those values registers a ``metrics_update_handler`` in its decorator to define how two sets of its metrics combine. The handler receives the accumulated metrics and the new values, and **mutates the accumulator in place**. It returns nothing. .. code-block:: python import time from silo.low_code import record_step_metrics, register_requestor def bean_metrics_handler(metrics_store, metrics_updates): """Combine two call counts into a correctly weighted average.""" new_count = metrics_updates.get("call_count", 0) new_avg = metrics_updates.get("avg_time", 0) old_count = metrics_store.get("call_count", 0) old_avg = metrics_store.get("avg_time", 0) total_count = new_count + old_count if not total_count: return total_time = old_avg * old_count + new_avg * new_count metrics_store["call_count"] = total_count metrics_store["avg_time"] = total_time / total_count @register_requestor(metrics_update_handler=bean_metrics_handler) def beans(step_args, collection, result_container): start = time.monotonic() result = collect_beans(step_args) record_step_metrics( {"call_count": 1, "avg_time": time.monotonic() - start}, collection, result_container.did, result_container.current_step_name, ) return result A single request records ``{"call_count": 1, "avg_time": 0.5}``, which is the same shape as the accumulated ``{"call_count": 200, "avg_time": 0.42}``, so the handler never needs to know whether it is merging one request or a whole window. Two requests, one taking 20 seconds and one taking 10, therefore accumulate to: .. code-block:: json {"call_count": 2, "avg_time": 15} .. note:: The handler is registered for the step, so :ref:`load_step_metrics ` uses it as well when ``merge_windows`` is set. The same definition of "combine" applies to recording, flushing, and merging windows. Where the handler is declared depends on the step type, and the two forms are not interchangeable: .. list-table:: Declaring the Handler :widths: 20 80 :header-rows: 1 * - Step Type - Declaration * - Requestor - The ``metrics_update_handler`` argument of the decorator, as above. A handler placed in ``metadata`` instead is discarded while the step is registered. * - Processor - A ``metrics_update_handler`` key inside ``metadata``. A handler passed as a decorator argument instead is discarded while the step is registered. .. warning:: A handler declared the wrong way for the step type is dropped silently. The step still records, but its metrics are merged by summing, which is easy to mistake for a handler that runs and misbehaves. Record one value that summing cannot produce, such as a minimum or a label, to confirm the handler is in use. A Processor records metrics exactly as a Requestor does, with its handler declared in ``metadata``: .. code-block:: python import time from silo.low_code import record_step_metrics, register_processor @register_processor(metadata={"metrics_update_handler": bean_metrics_handler}) def count_beans(result, collection, result_container): start = time.monotonic() counted = {key: len(value) for key, value in result.items()} record_step_metrics( {"call_count": 1, "avg_time": time.monotonic() - start}, collection, result_container.did, result_container.current_step_name, ) return counted Reading a Custom Step's Metrics ------------------------------- A custom step's metrics are read with the same step as any other, using the name the step was registered under: .. code-block:: yaml low_code: version: 2 steps: - load_step_metrics: step_name: "beans" lookback_minutes: 15 Which returns one entry per collection window that recorded anything: .. code-block:: json { "1784840100": {"call_count": 2, "avg_time": 15}, "1784840400": {"call_count": 3, "avg_time": 12.5} } Reading with ``merge_windows`` additionally requires the custom step to be registered in the Dynamic Application performing the read, since that is where its handler is looked up. Include the snippet that registers the step even when the step itself is not part of the Snippet Argument being read. Handler Requirements -------------------- A handler is called more than once for the same values, in more than one process, so it must be written to merge repeatedly without distorting the result: * **Every value is a delta.** A handler is called once per recording to fold that recording into the in-memory buffer, again at flush time to fold the buffer into the cached entry, and again per window when ``merge_windows`` is used. Both arguments always share the same shape. * **Derive, do not carry.** Accumulate totals and counts, then compute averages from them. Summing an average, or rounding a running total, compounds error on every merge. * **Widen bounds, union sets.** A minimum or maximum is merged by comparison, not addition. Lists of identifiers are merged by union. * **Keep values JSON-serializable.** Metrics are stored as JSON, so use ``int``, ``float``, ``str``, ``bool``, ``list``, ``dict``, and ``None``. A ``set`` or ``tuple`` does not survive the round trip, and a dictionary key that is not a string is read back as a string. * **Tolerate what is already cached.** The accumulator is empty the first time a window is written, and after that it is read from a cache entry that is shared between processes and outlives a PowerPack upgrade, so it can hold values recorded by an earlier version of the step. Read from it with defaults and validate what is being merged rather than assuming the current shape. * **Keep the number of keys bounded.** A key per URL or per command is useful; a key per request ID or timestamp grows the cached entry without limit. .. warning:: An exception raised inside a handler is contained but costs data. Raising while recording discards that request's metrics and returns ``False`` from ``record_step_metrics``; raising during the flush discards the buffered entry for the window; raising while merging windows skips that window. Each failure is logged as a warning. .. _step_metrics_troubleshooting: Troubleshooting =============== .. list-table:: Common Issues :widths: 40 60 :header-rows: 1 * - Symptom - Things to Check * - ``load_step_metrics`` returns nothing - The execution that was supposed to record the metrics did not opt in, the requested window has not been flushed yet, or nothing was recorded for that window. The log message ``Metrics cache has not yet been populated.`` is written at the debug level when the read found no entries. * - Metrics are missing for the most recent collection - The current collection window is never returned, since metrics are flushed at the end of an execution. Increase ``lookback_minutes`` so that at least one completed window is covered. * - Metrics were recorded but cannot be read - The read must resolve to the same step name, device, and credential the metrics were recorded under. Check ``step_name``, and set ``stat_align`` or ``cred_id`` if the reading Dynamic Application aligns to a different device in the relationship or to a different credential. * - The ``record_metrics`` step argument seems to be ignored - The aligned credential defines the field and therefore decides, whatever the step asks for. Enable ``Record Step Metrics`` on the credential, or check that the value asking for metrics is ``True`` or ``true`` rather than ``1`` or ``yes``. * - Nothing is recorded even though the step opted in - The feature may be disabled on the collector. ``metrics_enabled`` in the ``slc`` section of ``silo.conf`` must not be ``false`` or ``0``. When it is disabled, the debug log states ``Metrics tracking is not enabled in silo.conf - No metrics were stored``. * - Nothing is returned and the log shows ``Failed to load step metrics.`` - The device could not be resolved, ``stat_align`` was not ``self``, ``parent``, or ``root``, or the cache read failed. The log entry includes the underlying error. * - ``merge_windows`` returns an empty ``data`` field - The step named by ``step_name`` is not registered in the collection performing the read, so its merge handler cannot be resolved. Include the snippet that registers a custom step in the Dynamic Application reading its metrics. * - Metrics older than a couple of hours are gone - Cached metrics expire two hours after they are written. Map them to a collection object to retain them. * - Values look lower than expected - A flush that cannot be completed discards the affected entry rather than risk double-counting it, and logs a warning. Search the logs for ``metrics:`` to see whether an entry was discarded or a lock timed out.