LSSTApplications  10.0-2-g4f67435,11.0.rc2+1,11.0.rc2+12,11.0.rc2+3,11.0.rc2+4,11.0.rc2+5,11.0.rc2+6,11.0.rc2+7,11.0.rc2+8
LSSTDataManagementBasePackage
timer.py
Go to the documentation of this file.
1 from __future__ import absolute_import, division
2 #
3 # LSST Data Management System
4 # Copyright 2008, 2009, 2010, 2011 LSST Corporation.
5 #
6 # This product includes software developed by the
7 # LSST Project (http://www.lsst.org/).
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 LSST License Statement and
20 # the GNU General Public License along with this program. If not,
21 # see <http://www.lsstcorp.org/LegalNotices/>.
22 #
23 """Utilities for measuring execution time.
24 """
25 import functools
26 import resource
27 import time
28 import datetime
29 
30 from lsst.pex.logging import Log
31 
32 __all__ = ["logInfo", "timeMethod"]
33 
34 def logPairs(obj, pairs, logLevel=Log.DEBUG):
35  """!Log (name, value) pairs to obj.metadata and obj.log
36 
37  @param obj a \ref task.Task "Task", or any other object with these two attributes:
38  * metadata an instance of lsst.daf.base.PropertyList (or other object with add(name, value) method)
39  * log an instance of lsst.pex.logging.Log
40  @param pairs a collection of (name, value) pairs
41  @param logLevel log level (an lsst.pex.logging.Log level constant, such as lsst.pex.logging.Log.DEBUG)
42  """
43  strList = []
44  for name, value in pairs:
45  try:
46  obj.metadata.add(name, value)
47  except Exception, e:
48  obj.log.fatal("%s.metadata.add(name=%r, value=%r) failed with error=%s" % \
49  (type(obj).__name__, name, value, e))
50  strList.append("%s=%s" % (name, value))
51  obj.log.log(logLevel, "; ".join(strList))
52 
53 def logInfo(obj, prefix, logLevel=Log.DEBUG):
54  """!Log timer information to obj.metadata and obj.log
55 
56  @param obj a \ref task.Task "Task", or any other object with these two attributes:
57  * metadata an instance of lsst.daf.base.PropertyList (or other object with add(name, value) method)
58  * log an instance of lsst.pex.logging.Log
59  @param prefix name prefix, the resulting entries are <prefix>CpuTime, etc.
60  For example timeMethod uses prefix = <methodName>Start
61  when the method begins and prefix = <methodName>End when the method ends.
62  @param logLevel log level (an lsst.pex.logging.Log level, constant such as lsst.pex.logging.Log.DEBUG)
63 
64 
65  Logged items include:
66  * Utc: UTC date in ISO format (only in metadata since log entries have timestamps)
67  * CpuTime: CPU time (seconds)
68  * MaxRss: maximum resident set size
69  All logged resource information is only for the current process; child processes are excluded
70  """
71  cpuTime = time.clock()
72  utcStr = datetime.datetime.utcnow().isoformat()
73  res = resource.getrusage(resource.RUSAGE_SELF)
74  obj.metadata.add(name = prefix + "Utc", value = utcStr) # log messages already have timestamps
75  logPairs(obj = obj,
76  pairs = [
77  (prefix + "CpuTime", cpuTime),
78  (prefix + "UserTime", res.ru_utime),
79  (prefix + "SystemTime", res.ru_stime),
80  (prefix + "MaxResidentSetSize", long(res.ru_maxrss)),
81  (prefix + "MinorPageFaults", long(res.ru_minflt)),
82  (prefix + "MajorPageFaults", long(res.ru_majflt)),
83  (prefix + "BlockInputs", long(res.ru_inblock)),
84  (prefix + "BlockOutputs", long(res.ru_oublock)),
85  (prefix + "VoluntaryContextSwitches", long(res.ru_nvcsw)),
86  (prefix + "InvoluntaryContextSwitches", long(res.ru_nivcsw)),
87  ],
88  logLevel = logLevel,
89  )
90 
91 def timeMethod(func):
92  """!Decorator to measure duration of a task method
93 
94  Writes various measures of time and possibly memory usage to the task's metadata;
95  all items are prefixed with the function name.
96 
97  To use:
98  \code
99  import lsst.pipe.base as pipeBase
100  class FooTask(pipeBase.Task):
101  ...
102 
103  @pipeBase.timeMethod
104  def run(self, ...): # or any other instance method you want to time
105  ...
106  \endcode
107 
108  @param func the method to wrap
109 
110  @warning This decorator only works with instance methods of Task, or any class with these attributes:
111  * metadata: an instance of lsst.daf.base.PropertyList (or other object with add(name, value) method)
112  * log: an instance of lsst.pex.logging.Log
113  """
114  @functools.wraps(func)
115  def wrapper(self, *args, **keyArgs):
116  logInfo(obj = self, prefix = func.__name__ + "Start")
117  try:
118  res = func(self, *args, **keyArgs)
119  finally:
120  logInfo(obj = self, prefix = func.__name__ + "End")
121  return res
122  return wrapper
def logPairs
Log (name, value) pairs to obj.metadata and obj.log.
Definition: timer.py:34
def logInfo
Log timer information to obj.metadata and obj.log.
Definition: timer.py:53
def timeMethod
Decorator to measure duration of a task method.
Definition: timer.py:91