Coverage for python / lsst / dax / apdb / timer.py: 19%

1# This file is part of dax_apdb. 

2# 

3# Developed for the LSST Data Management System. 

4# This product includes software developed by the LSST Project 

5# (http://www.lsst.org). 

6# See the COPYRIGHT file at the top-level directory of this distribution 

7# for details of code ownership. 

8# 

9# This program is free software: you can redistribute it and/or modify 

10# it under the terms of the GNU General Public License as published by 

11# the Free Software Foundation, either version 3 of the License, or 

12# (at your option) any later version. 

13# 

14# This program is distributed in the hope that it will be useful, 

15# but WITHOUT ANY WARRANTY; without even the implied warranty of 

16# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the 

17# GNU General Public License for more details. 

18# 

19# You should have received a copy of the GNU General Public License 

20# along with this program. If not, see <http://www.gnu.org/licenses/>. 

21 

22"""Module with methods to return timing information. 

23 

24This was developed as a part of a prototype for performance studies. It 

25could probably be removed in the production system. 

26""" 

27 

28from __future__ import annotations 

29 

30import logging 

31import resource 

32import time 

33from collections.abc import Mapping 

34from typing import Any 

35 

36from .monitor import MonAgent 

37 

38_TagsType = Mapping[str, str | int] 

39 

40 

41class Timer: 

42 """Instance of this class can be used to track consumed time. 

43 

44 Parameters 

45 ---------- 

46 name : `str` 

47 Timer name, will be use for reporting to both monitoring and logging. 

48 Typically the name should look like an identifier for ease of use with 

49 downstream monitoring software. 

50 *args : `MonAgent` or `logging.Logger` 

51 Positional arguments can include a combination of `MonAgent` and 

52 `logging.Logger` instances. They will be used to report accumulated 

53 times on exit from context or by calling `dump` method directly. 

54 tags : `~collections.abc.Mapping` [`str`, `str` or `int`], optional 

55 Keyword argument, additional tags added to monitoring report and 

56 logging output. 

57 log_level : `int`, optional 

58 Keyword argument, level used for logging output, default is 

59 `logging.INFO`. 

60 

61 Notes 

62 ----- 

63 This class is also a context manager and can be used in a `with` statement. 

64 By default it prints consumed CPU time and real time spent in a context. 

65 

66 Example: 

67 

68 with Timer("SelectTimer", logger): 

69 engine.execute('SELECT ...') 

70 

71 """ 

72 

73 def __init__( 

74 self, 

75 name: str, 

76 *args: MonAgent | logging.Logger, 

77 tags: _TagsType | None = None, 

78 log_level: int = logging.INFO, 

79 ): 

80 self._name = name 

81 self._mon_agents: list[MonAgent] = [] 

82 self._loggers: list[logging.Logger] = [] 

83 self._tags = tags 

84 self._log_level = log_level 

85 

86 for arg in args: 

87 if isinstance(arg, MonAgent): 

88 self._mon_agents.append(arg) 

89 elif isinstance(arg, logging.Logger): 

90 self._loggers.append(arg) 

91 

92 self._startReal = -1.0 

93 self._startUser = -1.0 

94 self._startSys = -1.0 

95 self._sumReal = 0.0 

96 self._sumUser = 0.0 

97 self._sumSys = 0.0 

98 

99 self._extra_values: dict[str, int | float] = {} 

100 

101 def add_values(self, **values: int | float) -> None: 

102 """Add values to dump together with timing information. 

103 

104 Parameters 

105 ---------- 

106 **values : int | float 

107 Key/values to add to timer information. 

108 """ 

109 self._extra_values.update(values) 

110 

111 def start(self) -> Timer: 

112 """Start timer.""" 

113 self._startReal = time.time() 

114 ru = resource.getrusage(resource.RUSAGE_SELF) 

115 self._startUser = ru.ru_utime 

116 self._startSys = ru.ru_stime 

117 return self 

118 

119 def stop(self) -> Timer: 

120 """Stop timer.""" 

121 if self._startReal > 0: 

122 self._sumReal += time.time() - self._startReal 

123 ru = resource.getrusage(resource.RUSAGE_SELF) 

124 self._sumUser += ru.ru_utime - self._startUser 

125 self._sumSys += ru.ru_stime - self._startSys 

126 self._startReal = -1.0 

127 self._startUser = -1.0 

128 self._startSys = -1.0 

129 return self 

130 

131 def dump(self) -> Timer: 

132 """Dump timer statistics""" 

133 for logger in self._loggers: 

134 logger.log(self._log_level, "%s", self) 

135 for agent in self._mon_agents: 

136 agent.add_record(self._name, values=self.as_dict(), tags=self._tags) 

137 return self 

138 

139 def accumulated(self) -> tuple[float, float, float]: 

140 """Return accumulated real, user, and system times in seconds.""" 

141 real = self._sumReal 

142 user = self._sumUser 

143 sys = self._sumSys 

144 if self._startReal > 0: 

145 real += time.time() - self._startReal 

146 ru = resource.getrusage(resource.RUSAGE_SELF) 

147 user += ru.ru_utime - self._startUser 

148 sys += ru.ru_stime - self._startSys 

149 return (real, user, sys) 

150 

151 def as_dict(self, prefix: str = "") -> dict[str, int | float]: 

152 """Return timers and extra values as dictionary.""" 

153 real, user, sys = self.accumulated() 

154 values = { 

155 f"{prefix}real": real, 

156 f"{prefix}user": user, 

157 f"{prefix}sys": sys, 

158 } 

159 values.update(self._extra_values) 

160 return values 

161 

162 def __str__(self) -> str: 

163 real, user, sys = self.accumulated() 

164 info = f"real={real:.3f} user={user:.3f} sys={sys:.3f}" 

165 if self._name: 

166 info = self._name + ": " + info 

167 if self._tags: 

168 info += f" (tags={self._tags})" 

169 return info 

170 

171 def __enter__(self) -> Timer: 

172 """Enter context, start timer""" 

173 self.start() 

174 return self 

175 

176 def __exit__(self, exc_type: type | None, exc_val: Any, exc_tb: Any) -> Any: 

177 """Exit context, stop and dump timer""" 

178 self.stop() 

179 if exc_type is None: 

180 self.dump() 

181 return False