Coverage for pySDC/core/timings.py: 100%

1import time 

2from pySDC.core.hooks import Hooks 

3 

4 

5class Timings(Hooks): 

6 """ 

7 Abstract base class for recoding timings 

8 

9 Attributes: 

10 __t0_setup (float): private variable to get starting time of setup 

11 __t0_run (float): private variable to get starting time of the run 

12 __t0_predict (float): private variable to get starting time of the predictor 

13 __t0_step (float): private variable to get starting time of the step 

14 __t0_iteration (float): private variable to get starting time of the iteration 

15 __t0_sweep (float): private variable to get starting time of the sweep 

16 __t0_comm (list): private variable to get starting time of the communication 

17 __t1_run (float): private variable to get end time of the run 

18 __t1_predict (float): private variable to get end time of the predictor 

19 __t1_step (float): private variable to get end time of the step 

20 __t1_iteration (float): private variable to get end time of the iteration 

21 __t1_sweep (float): private variable to get end time of the sweep 

22 __t1_setup (float): private variable to get end time of setup 

23 __t1_comm (list): private variable to hold timing of the communication (!) 

24 """ 

25 

26 prefix = '' 

27 

28 def _compute_time_elapsed(self, event_after, event_before): 

29 raise NotImplementedError 

30 

31 def _get_event(self): 

32 raise NotImplementedError 

33 

34 def __init__(self): 

35 super().__init__() 

36 self.__t0_setup = None 

37 self.__t0_run = None 

38 self.__t0_predict = None 

39 self.__t0_step = None 

40 self.__t0_iteration = None 

41 self.__t0_sweep = None 

42 self.__t0_comm = [] 

43 self.__t1_run = None 

44 self.__t1_predict = None 

45 self.__t1_step = None 

46 self.__t1_iteration = None 

47 self.__t1_sweep = None 

48 self.__t1_setup = None 

49 self.__t1_comm = [] 

50 

51 def pre_setup(self, step, level_number): 

52 """ 

53 Default routine called before setup starts 

54 

55 Args: 

56 step (pySDC.Step.step): the current step 

57 level_number (int): the current level number 

58 """ 

59 super().pre_setup(step, level_number) 

60 self.__t0_setup = self._get_event() 

61 

62 def pre_run(self, step, level_number): 

63 """ 

64 Default routine called before time-loop starts 

65 

66 Args: 

67 step (pySDC.Step.step): the current step 

68 level_number (int): the current level number 

69 """ 

70 super().pre_run(step, level_number) 

71 self.__t0_run = self._get_event() 

72 

73 def pre_predict(self, step, level_number): 

74 """ 

75 Default routine called before predictor starts 

76 

77 Args: 

78 step (pySDC.Step.step): the current step 

79 level_number (int): the current level number 

80 """ 

81 super().pre_predict(step, level_number) 

82 self.__t0_predict = self._get_event() 

83 

84 def pre_step(self, step, level_number): 

85 """ 

86 Hook called before each step 

87 

88 Args: 

89 step (pySDC.Step.step): the current step 

90 level_number (int): the current level number 

91 """ 

92 super().pre_step(step, level_number) 

93 self.__t0_step = self._get_event() 

94 

95 def pre_iteration(self, step, level_number): 

96 """ 

97 Default routine called before iteration starts 

98 

99 Args: 

100 step (pySDC.Step.step): the current step 

101 level_number (int): the current level number 

102 """ 

103 super().pre_iteration(step, level_number) 

104 self.__t0_iteration = self._get_event() 

105 

106 def pre_sweep(self, step, level_number): 

107 """ 

108 Default routine called before sweep starts 

109 

110 Args: 

111 step (pySDC.Step.step): the current step 

112 level_number (int): the current level number 

113 """ 

114 super().pre_sweep(step, level_number) 

115 self.__t0_sweep = self._get_event() 

116 

117 def pre_comm(self, step, level_number): 

118 """ 

119 Default routine called before communication starts 

120 

121 Args: 

122 step (pySDC.Step.step): the current step 

123 level_number (int): the current level number 

124 """ 

125 super().pre_comm(step, level_number) 

126 if len(self.__t0_comm) >= level_number + 1: 

127 self.__t0_comm[level_number] = self._get_event() 

128 else: 

129 while len(self.__t0_comm) < level_number: 

130 self.__t0_comm.append(None) 

131 self.__t0_comm.append(self._get_event()) 

132 while len(self.__t1_comm) <= level_number: 

133 self.__t1_comm.append(0.0) 

134 assert len(self.__t0_comm) == level_number + 1 

135 assert len(self.__t1_comm) == level_number + 1 

136 

137 def post_comm(self, step, level_number, add_to_stats=False): 

138 """ 

139 Default routine called after each communication 

140 

141 Args: 

142 step (pySDC.Step.step): the current step 

143 level_number (int): the current level number 

144 add_to_stats (bool): set if result should go to stats object 

145 """ 

146 super().post_comm(step, level_number) 

147 assert len(self.__t1_comm) >= level_number + 1 

148 self.__t1_comm[level_number] += self._compute_time_elapsed(self._get_event(), self.__t0_comm[level_number]) 

149 

150 if add_to_stats: 

151 L = step.levels[level_number] 

152 

153 self.add_to_stats( 

154 process=step.status.slot, 

155 process_sweeper=L.sweep.rank, 

156 time=L.time, 

157 level=L.level_index, 

158 iter=step.status.iter, 

159 sweep=L.status.sweep, 

160 type=f'{self.prefix}timing_comm', 

161 value=self.__t1_comm[level_number], 

162 ) 

163 self.__t1_comm[level_number] = 0.0 

164 

165 def post_sweep(self, step, level_number): 

166 """ 

167 Default routine called after each sweep 

168 

169 Args: 

170 step (pySDC.Step.step): the current step 

171 level_number (int): the current level number 

172 """ 

173 super().post_sweep(step, level_number) 

174 self.__t1_sweep = self._get_event() 

175 

176 L = step.levels[level_number] 

177 

178 self.add_to_stats( 

179 process=step.status.slot, 

180 process_sweeper=L.sweep.rank, 

181 time=L.time, 

182 level=L.level_index, 

183 iter=step.status.iter, 

184 sweep=L.status.sweep, 

185 type=f'{self.prefix}timing_sweep', 

186 value=self._compute_time_elapsed(self.__t1_sweep, self.__t0_sweep), 

187 ) 

188 

189 def post_iteration(self, step, level_number): 

190 """ 

191 Default routine called after each iteration 

192 

193 Args: 

194 step (pySDC.Step.step): the current step 

195 level_number (int): the current level number 

196 """ 

197 super().post_iteration(step, level_number) 

198 self.__t1_iteration = self._get_event() 

199 

200 L = step.levels[level_number] 

201 

202 self.add_to_stats( 

203 process=step.status.slot, 

204 process_sweeper=L.sweep.rank, 

205 time=L.time, 

206 level=L.level_index, 

207 iter=step.status.iter, 

208 sweep=L.status.sweep, 

209 type=f'{self.prefix}timing_iteration', 

210 value=self._compute_time_elapsed(self.__t1_iteration, self.__t0_iteration), 

211 ) 

212 

213 def post_step(self, step, level_number): 

214 """ 

215 Default routine called after each step or block 

216 

217 Args: 

218 step (pySDC.Step.step): the current step 

219 level_number (int): the current level number 

220 """ 

221 super().post_step(step, level_number) 

222 self.__t1_step = self._get_event() 

223 

224 L = step.levels[level_number] 

225 

226 self.add_to_stats( 

227 process=step.status.slot, 

228 process_sweeper=L.sweep.rank, 

229 time=L.time, 

230 level=L.level_index, 

231 iter=step.status.iter, 

232 sweep=L.status.sweep, 

233 type=f'{self.prefix}timing_step', 

234 value=self._compute_time_elapsed(self.__t1_step, self.__t0_step), 

235 ) 

236 

237 def post_predict(self, step, level_number): 

238 """ 

239 Default routine called after each predictor 

240 

241 Args: 

242 step (pySDC.Step.step): the current step 

243 level_number (int): the current level number 

244 """ 

245 super().post_predict(step, level_number) 

246 self.__t1_predict = self._get_event() 

247 

248 L = step.levels[level_number] 

249 

250 self.add_to_stats( 

251 process=step.status.slot, 

252 process_sweeper=L.sweep.rank, 

253 time=L.time, 

254 level=L.level_index, 

255 iter=step.status.iter, 

256 sweep=L.status.sweep, 

257 type=f'{self.prefix}timing_predictor', 

258 value=self._compute_time_elapsed(self.__t1_predict, self.__t0_predict), 

259 ) 

260 

261 def post_run(self, step, level_number): 

262 """ 

263 Default routine called after each run 

264 

265 Args: 

266 step (pySDC.Step.step): the current step 

267 level_number (int): the current level number 

268 """ 

269 super().post_run(step, level_number) 

270 self.__t1_run = self._get_event() 

271 t_run = self._compute_time_elapsed(self.__t1_run, self.__t0_run) 

272 

273 L = step.levels[level_number] 

274 

275 self.add_to_stats( 

276 process=step.status.slot, 

277 process_sweeper=L.sweep.rank, 

278 time=L.time, 

279 level=L.level_index, 

280 iter=step.status.iter, 

281 sweep=L.status.sweep, 

282 type=f'{self.prefix}timing_run', 

283 value=t_run, 

284 ) 

285 if step.status.first: 

286 self.logger.info(f'Finished run after {t_run:.2e}s') 

287 

288 def post_setup(self, step, level_number): 

289 """ 

290 Default routine called after setup 

291 

292 Args: 

293 step (pySDC.Step.step): the current step 

294 level_number (int): the current level number 

295 """ 

296 super().post_setup(step, level_number) 

297 self.__t1_setup = self._get_event() 

298 

299 self.add_to_stats( 

300 process=-1, 

301 process_sweeper=-1, 

302 time=-1, 

303 level=-1, 

304 iter=-1, 

305 sweep=-1, 

306 type=f'{self.prefix}timing_setup', 

307 value=self._compute_time_elapsed(self.__t1_setup, self.__t0_setup), 

308 ) 

309 

310 

311class CPUTimings(Timings): 

312 """ 

313 Hook for recording CPU timings of important operations during a pySDC run. 

314 """ 

315 

316 def _compute_time_elapsed(self, event_after, event_before): 

317 return event_after - event_before 

318 

319 def _get_event(self): 

320 return time.perf_counter()