Coverage for python / lsst / utils / timer.py: 20%
202 statements
« prev ^ index » next coverage.py v7.13.5, created at 2026-04-26 08:43 +0000
1# This file is part of utils.
2#
3# Developed for the LSST Data Management System.
4# This product includes software developed by the LSST Project
5# (https://www.lsst.org).
6# See the COPYRIGHT file at the top-level directory of this distribution
7# for details of code ownership.
8#
9# Use of this source code is governed by a 3-clause BSD-style
10# license that can be found in the LICENSE file.
11#
13"""Utilities for measuring execution time."""
15from __future__ import annotations
17__all__ = ["duration_from_timeMethod", "logInfo", "profile", "timeMethod", "time_this"]
19import dataclasses
20import datetime
21import functools
22import logging
23import os
24import platform
25import sys
26import time
27import traceback
28from collections.abc import Callable, Collection, Iterable, Iterator, MutableMapping
29from contextlib import contextmanager, suppress
30from typing import TYPE_CHECKING, Any, TypeVar, overload
32from astropy import units as u
34from .introspection import find_outside_stacklevel
35from .logging import LsstLoggers, _is_structlog_logger
36from .usage import _get_current_rusage, get_current_mem_usage, get_peak_mem_usage
38if TYPE_CHECKING:
39 import cProfile
42_LOG = logging.getLogger(__name__)
45def _add_to_metadata(metadata: MutableMapping, name: str, value: Any) -> None:
46 """Add a value to dict-like object, creating list as needed.
48 The list grows as more values are added for that key.
50 Parameters
51 ----------
52 metadata : `dict`-like, optional
53 `dict`-like object that can store keys. Uses `add()` method if
54 one is available, else creates list and appends value if needed.
55 name : `str`
56 The key to use in the metadata dictionary.
57 value : Any
58 Value to store in the list.
59 """
60 try:
61 try:
62 # PropertySet should always prefer LongLong for integers
63 metadata.addLongLong(name, value) # type: ignore
64 except (TypeError, AttributeError):
65 metadata.add(name, value) # type: ignore
66 except AttributeError:
67 pass
68 else:
69 return
71 # Fallback code where `add` is not implemented.
72 if name not in metadata:
73 metadata[name] = []
74 metadata[name].append(value)
77def logPairs(
78 obj: Any,
79 pairs: Collection[tuple[str, Any]],
80 logLevel: int = logging.DEBUG,
81 metadata: MutableMapping | None = None,
82 logger: LsstLoggers | None = None,
83 stacklevel: int | None = None,
84) -> None:
85 """Log ``(name, value)`` pairs to ``obj.metadata`` and ``obj.log``.
87 Parameters
88 ----------
89 obj : `object`
90 An object with one or both of these two attributes:
92 - ``metadata`` a `dict`-like container for storing metadata.
93 Can use the ``add(name, value)`` method if found, else will append
94 entries to a list.
95 - ``log`` an instance of `logging.Logger` or subclass.
97 If `None`, at least one of ``metadata`` or ``logger`` should be passed
98 or this function will do nothing.
99 pairs : sequence
100 A sequence of ``(name, value)`` pairs, with value typically numeric.
101 logLevel : `int, optional
102 Log level (an `logging` level constant, such as `logging.DEBUG`).
103 metadata : `collections.abc.MutableMapping`, optional
104 Metadata object to write entries to. Ignored if `None`.
105 logger : `logging.Logger` or `lsst.utils.logging.LsstLogAdapter`
106 Log object to write entries to. Ignored if `None`.
107 stacklevel : `int`, optional
108 The stack level to pass to the logger to adjust which stack frame
109 is used to report the file information. If `None` the stack level
110 is computed such that it is reported as the first package outside
111 of the utils package. If a value is given here it is adjusted by
112 1 to account for this caller.
113 """
114 if obj is not None:
115 if metadata is None:
116 with suppress(AttributeError):
117 metadata = obj.metadata
119 if logger is None:
120 with suppress(AttributeError):
121 logger = obj.log
123 strList = []
124 for name, value in pairs:
125 if metadata is not None:
126 _add_to_metadata(metadata, name, value)
127 strList.append(f"{name}={value}")
128 if logger is not None:
129 # Want the file associated with this log message to be that
130 # of the caller. This is expensive so only do it if we know the
131 # message will be issued.
132 timer_logger = logging.getLogger("timer." + logger.name)
133 if timer_logger.isEnabledFor(logLevel):
134 if stacklevel is None:
135 stacklevel = find_outside_stacklevel("lsst.utils")
136 else:
137 # Account for the caller stack.
138 stacklevel += 1
139 timer_logger.log(logLevel, "; ".join(strList), stacklevel=stacklevel)
142def logInfo(
143 obj: Any,
144 prefix: str,
145 logLevel: int = logging.DEBUG,
146 metadata: MutableMapping | None = None,
147 logger: LsstLoggers | None = None,
148 stacklevel: int | None = None,
149) -> None:
150 """Log timer information to ``obj.metadata`` and ``obj.log``.
152 Parameters
153 ----------
154 obj : `object`
155 An object with both or one these two attributes:
157 - ``metadata`` a `dict`-like container for storing metadata.
158 Can use the ``add(name, value)`` method if found, else will append
159 entries to a list.
160 - ``log`` an instance of `logging.Logger` or subclass.
162 If `None`, at least one of ``metadata`` or ``logger`` should be passed
163 or this function will do nothing.
164 prefix : `str`
165 Name prefix, the resulting entries are ``CpuTime``, etc.. For example
166 `timeMethod` uses ``prefix = Start`` when the method begins and
167 ``prefix = End`` when the method ends.
168 logLevel : `int`, optional
169 Log level (a `logging` level constant, such as `logging.DEBUG`).
170 metadata : `collections.abc.MutableMapping`, optional
171 Metadata object to write entries to, overriding ``obj.metadata``.
172 logger : `logging.Logger` or `lsst.utils.logging.LsstLogAdapter`
173 Log object to write entries to, overriding ``obj.log``.
174 stacklevel : `int`, optional
175 The stack level to pass to the logger to adjust which stack frame
176 is used to report the file information. If `None` the stack level
177 is computed such that it is reported as the first package outside
178 of the utils package. If a value is given here it is adjusted by
179 1 to account for this caller.
181 Notes
182 -----
183 Logged items include:
185 - ``Utc``: UTC date in ISO format (only in metadata since log entries have
186 timestamps).
187 - ``CpuTime``: System + User CPU time (seconds). This should only be used
188 in differential measurements; the time reference point is undefined.
189 - ``MaxRss``: maximum resident set size. Always in bytes.
191 All logged resource information is only for the current process; child
192 processes are excluded.
194 The metadata will be updated with a ``__version__`` field to indicate the
195 version of the items stored. If there is no version number it is assumed
196 to be version 0.
198 * Version 0: ``MaxResidentSetSize`` units are platform-dependent.
199 * Version 1: ``MaxResidentSetSize`` will be stored in bytes.
200 """
201 if metadata is None and obj is not None:
202 with suppress(AttributeError):
203 metadata = obj.metadata
205 if metadata is not None:
206 # Log messages already have timestamps.
207 if sys.version_info < (3, 11, 0):
208 now = datetime.datetime.utcnow()
209 else:
210 now = datetime.datetime.now(datetime.UTC)
211 utcStr = now.isoformat()
212 _add_to_metadata(metadata, name=prefix + "Utc", value=utcStr)
214 # Force a version number into the metadata.
215 # v1: Ensure that max_rss field is always bytes.
216 metadata["__version__"] = 1
218 # Add node information.
219 metadata["nodeName"] = platform.node()
220 if stacklevel is not None:
221 # Account for the caller of this routine not knowing that we
222 # are going one down in the stack.
223 stacklevel += 1
225 usage = _get_current_rusage()
226 logPairs(
227 obj=obj,
228 pairs=[(prefix + k[0].upper() + k[1:], v) for k, v in usage.dict().items()],
229 logLevel=logLevel,
230 metadata=metadata,
231 logger=logger,
232 stacklevel=stacklevel,
233 )
236_F = TypeVar("_F", bound=Callable)
239@overload
240def timeMethod(_func: _F) -> _F: ... 240 ↛ exitline 240 didn't return from function 'timeMethod' because
243@overload
244def timeMethod( 244 ↛ exitline 244 didn't return from function 'timeMethod' because
245 *,
246 metadata: MutableMapping | None = None,
247 logger: LsstLoggers | None = None,
248 logLevel: int = logging.DEBUG,
249) -> Callable[[_F], _F]: ...
252def timeMethod(
253 _func: Any | None = None,
254 *,
255 metadata: MutableMapping | None = None,
256 logger: LsstLoggers | None = None,
257 logLevel: int = logging.DEBUG,
258) -> Callable:
259 """Measure duration of a method.
261 Set LSST_UTILS_DISABLE_TIMER in your environment to disable this method.
263 Parameters
264 ----------
265 _func : `~collections.abc.Callable` or `None`
266 The method to wrap.
267 metadata : `collections.abc.MutableMapping`, optional
268 Metadata to use as override if the instance object attached
269 to this timer does not support a ``metadata`` property.
270 logger : `logging.Logger` or `lsst.utils.logging.LsstLogAdapter`, optional
271 Logger to use when the class containing the decorated method does not
272 have a ``log`` property.
273 logLevel : `int`, optional
274 Log level to use when logging messages. Default is `~logging.DEBUG`.
276 Notes
277 -----
278 Writes various measures of time and possibly memory usage to the
279 metadata; all items are prefixed with the function name.
281 .. warning::
283 This decorator only works with instance methods of any class
284 with these attributes:
286 - ``metadata``: an instance of `collections.abc.Mapping`. The ``add``
287 method will be used if available, else entries will be added to a
288 list.
289 - ``log``: an instance of `logging.Logger` or subclass.
291 Examples
292 --------
293 To use:
295 .. code-block:: python
297 import lsst.utils as utils
298 import lsst.pipe.base as pipeBase
299 class FooTask(pipeBase.Task):
300 pass
302 @utils.timeMethod
303 def run(self, ...): # or any other instance method you want to time
304 pass
305 """
307 def decorator_timer(func: Callable) -> Callable:
308 @functools.wraps(func)
309 def timeMethod_wrapper(self: Any, *args: Any, **keyArgs: Any) -> Any:
310 # Adjust the stacklevel to account for the wrappers.
311 # stacklevel 1 would make the log message come from this function
312 # but we want it to come from the file that defined the method
313 # so need to increment by 1 to get to the caller.
314 stacklevel = 2
315 logInfo(
316 obj=self,
317 prefix=func.__name__ + "Start",
318 metadata=metadata,
319 logger=logger,
320 logLevel=logLevel,
321 stacklevel=stacklevel,
322 )
323 try:
324 res = func(self, *args, **keyArgs)
325 finally:
326 logInfo(
327 obj=self,
328 prefix=func.__name__ + "End",
329 metadata=metadata,
330 logger=logger,
331 logLevel=logLevel,
332 stacklevel=stacklevel,
333 )
334 return res
336 return timeMethod_wrapper
338 if "LSST_UTILS_DISABLE_TIMER" in os.environ: 338 ↛ 339line 338 didn't jump to line 339 because the condition on line 338 was never true
339 if _func is not None:
340 return _func
341 else:
343 def pass_through(func: Callable) -> Callable:
344 """Pass through decorator.
346 This decorator will not appear in the call stack.
347 """
348 return func
350 return pass_through
352 if _func is None:
353 return decorator_timer
354 else:
355 return decorator_timer(_func)
358@dataclasses.dataclass
359class _TimerResult:
360 duration: float = 0.0
361 """Duration of context in seconds."""
362 mem_current_usage: float | None = None
363 """Memory usage at end of context in requested units."""
364 mem_peak_delta: float | None = None
365 """Peak differential between entering and leaving context."""
366 mem_current_delta: float | None = None
367 """Difference in usage between entering and leaving context."""
370@contextmanager
371def time_this(
372 log: LsstLoggers | None = None,
373 msg: str | None = None,
374 level: int = logging.DEBUG,
375 prefix: str | None = "timer",
376 args: Iterable[Any] = (),
377 kwargs: dict[str, Any] | None = None,
378 mem_usage: bool = False,
379 mem_child: bool = False,
380 mem_unit: u.Unit = u.byte,
381 mem_fmt: str = ".0f",
382 force_mem_usage: bool = False,
383) -> Iterator[_TimerResult]:
384 """Time the enclosed block and issue a log message.
386 Parameters
387 ----------
388 log : `logging.Logger`, optional
389 Logger to use to report the timer message. The root logger will
390 be used if none is given. Is also allowed to be a `structlog` bound
391 logger.
392 msg : `str`, optional
393 Context to include in log message.
394 level : `int`, optional
395 Python logging level to use to issue the log message. If the
396 code block raises an exception the log message will include some
397 information about the exception that occurred.
398 prefix : `str`, optional
399 Prefix to use to prepend to the supplied logger to
400 create a new logger to use instead. No prefix is used if the value
401 is set to `None`. Defaults to "timer".
402 args : `~collections.abc.Iterable` [ `typing.Any` ]
403 Additional parameters passed to the log command that should be
404 written to ``msg``.
405 kwargs : `dict`, optional
406 Additional keyword parameters passed to the log command. If a Structlog
407 is used then these will be added to the structured data. Otherwise
408 they will be converted to a single string for inclusion in the log
409 message.
410 mem_usage : `bool`, optional
411 Flag indicating whether to include the memory usage in the report.
412 Defaults, to False. Does nothing if the log message will not be
413 generated.
414 mem_child : `bool`, optional
415 Flag indication whether to include memory usage of the child processes.
416 mem_unit : `astropy.units.Unit`, optional
417 Unit to use when reporting the memory usage. Defaults to bytes.
418 mem_fmt : `str`, optional
419 Format specifier to use when displaying values related to memory usage.
420 Defaults to '.0f'.
421 force_mem_usage : `bool`, optional
422 If `True` memory usage is always calculated even if the log message
423 will not be delivered. Use this if you want the information recorded
424 by the context manager.
426 Yields
427 ------
428 timer_result : `_TimerResult`
429 Simple data class containing the duration of the block in seconds via
430 the ``duration`` property.
431 """
432 if log is None:
433 log = logging.getLogger()
434 is_structlog = _is_structlog_logger(log)
435 if prefix and not is_structlog:
436 # Struct log loggers do not have a name property and so the prefix
437 # is not applied to them.
438 log_name = f"{prefix}.{log.name}" if not isinstance(log, logging.RootLogger) else prefix
439 log = logging.getLogger(log_name)
441 # Some structured data that can be used if we have been given a
442 # structlog logger.
443 structured_args: dict[str, Any] = {}
445 start = time.time()
447 if mem_usage and not log.isEnabledFor(level):
448 mem_usage = False
449 if force_mem_usage:
450 mem_usage = True
452 if mem_usage:
453 current_usages_start = get_current_mem_usage()
454 peak_usages_start = get_peak_mem_usage()
456 timer_result = _TimerResult()
457 errmsg = ""
458 try:
459 yield timer_result
460 except BaseException as e:
461 frame, lineno = list(traceback.walk_tb(e.__traceback__))[-1]
462 errmsg = f"{e!r} @ {frame.f_code.co_filename}:{lineno}"
463 raise
464 finally:
465 end = time.time()
467 # The message is pre-inserted to allow the logger to expand
468 # the additional args provided. Make that easier by converting
469 # the None message to empty string.
470 if msg is None:
471 msg = ""
473 # Convert user provided parameters (if any) to mutable sequence to make
474 # mypy stop complaining when additional parameters will be added below.
475 params = list(args) if args else []
477 duration = end - start
478 timer_result.duration = duration
480 # Specify stacklevel to ensure the message is reported from the
481 # caller (1 is this file, 2 is contextlib, 3 is user)
482 params += (": " if msg else "", duration)
483 msg += "%sTook %.4f seconds"
484 structured_args["duration"] = duration
485 if errmsg:
486 params += (f" (timed code triggered exception of {errmsg!r})",)
487 msg += "%s"
488 if mem_usage:
489 current_usages_end = get_current_mem_usage()
490 peak_usages_end = get_peak_mem_usage()
492 current_deltas = [end - start for end, start in zip(current_usages_end, current_usages_start)]
493 peak_deltas = [end - start for end, start in zip(peak_usages_end, peak_usages_start)]
495 current_usage = current_usages_end[0]
496 current_delta = current_deltas[0]
497 peak_delta = peak_deltas[0]
498 if mem_child:
499 current_usage += current_usages_end[1]
500 current_delta += current_deltas[1]
501 peak_delta += peak_deltas[1]
503 if not mem_unit.is_equivalent(u.byte):
504 _LOG.warning("Invalid memory unit '%s', using '%s' instead", mem_unit, u.byte)
505 mem_unit = u.byte
507 current_usage = current_usage.to(mem_unit)
508 current_delta = current_delta.to(mem_unit)
509 peak_delta = peak_delta.to(mem_unit)
511 timer_result.mem_current_usage = float(current_usage.value)
512 timer_result.mem_current_delta = float(current_delta.value)
513 timer_result.mem_peak_delta = float(peak_delta.value)
515 msg += (
516 f"; current memory usage: {current_usage:{mem_fmt}}"
517 f", delta: {current_delta:{mem_fmt}}"
518 f", peak delta: {peak_delta:{mem_fmt}}"
519 )
520 structured_args["mem_current_usage"] = float(current_usage.value)
521 structured_args["mem_current_delta"] = float(current_delta.value)
522 structured_args["mem_peak_delta"] = float(peak_delta.value)
523 if not is_structlog:
524 # Can only use the structured content if we have structlog logger
525 # but stacklevel is only supported by standard loggers.
526 structured_args = {"stacklevel": 3}
527 if kwargs is not None:
528 msg += " %s"
529 params += ("; ".join(f"{k}={v!r}" for k, v in kwargs.items()),)
530 elif kwargs:
531 structured_args.update(kwargs)
533 log.log(level, msg, *params, **structured_args)
536@contextmanager
537def profile(filename: str | None, log: LsstLoggers | None = None) -> Iterator[cProfile.Profile | None]:
538 """Profile the enclosed code block and save the result to a file.
540 Parameters
541 ----------
542 filename : `str` or `None`
543 Filename to which to write profile (profiling disabled if `None` or
544 empty string).
545 log : `logging.Logger` or `lsst.utils.logging.LsstLogAdapter`, optional
546 Log object for logging the profile operations.
548 Yields
549 ------
550 prof : `cProfile.Profile` or `None`
551 If profiling is enabled, the context manager returns the
552 `cProfile.Profile` object (otherwise it returns `None`),
553 which allows additional control over profiling.
555 Examples
556 --------
557 You can obtain the `cProfile.Profile` object using the "as" clause, e.g.:
559 .. code-block:: python
561 with profile(filename) as prof:
562 runYourCodeHere()
564 The output cumulative profile can be printed with a command-line like:
566 .. code-block:: bash
568 python -c 'import pstats; \
569 pstats.Stats("<filename>").sort_stats("cumtime").print_stats(30)'
570 """
571 if not filename:
572 # Nothing to do
573 yield None
574 return
575 from cProfile import Profile
577 profile = Profile()
578 if log is not None:
579 log.info("Enabling cProfile profiling")
580 profile.enable()
581 yield profile
582 profile.disable()
583 profile.dump_stats(filename)
584 if log is not None:
585 log.info("cProfile stats written to %s", filename)
588def duration_from_timeMethod(
589 metadata: MutableMapping | None, method_name: str, clock: str = "Cpu"
590) -> float | None:
591 """Parse the metadata entries from ``timeMethod`` and return a duration.
593 Parameters
594 ----------
595 metadata : `collections.abc.MutableMapping`
596 The Task metadata that timing metrics were added to.
597 method_name : `str`
598 Name of the timed method to extract a duration for.
599 clock : `str`, optional
600 Options are "Cpu", "User", "System", or "Utc".
602 Returns
603 -------
604 duration : `float`
605 The time elapsed between the start and end of the timed method.
606 """
607 if metadata is None:
608 return None
609 if clock.lower() == "utc":
610 start = metadata[method_name + "StartUtc"]
611 end = metadata[method_name + "EndUtc"]
612 else:
613 start = metadata[method_name + "Start" + clock + "Time"]
614 end = metadata[method_name + "End" + clock + "Time"]
615 if isinstance(start, list):
616 start = start[-1]
617 if isinstance(end, list):
618 end = end[-1]
619 if isinstance(start, str) and isinstance(end, str):
620 return (datetime.datetime.fromisoformat(end) - datetime.datetime.fromisoformat(start)).total_seconds()
621 else:
622 return end - start