Package mvpa :: Package misc :: Module verbosity
[hide private]
[frames] | no frames]

Source Code for Module mvpa.misc.verbosity

  1  #emacs: -*- mode: python-mode; py-indent-offset: 4; indent-tabs-mode: nil -*- 
  2  #ex: set sts=4 ts=4 sw=4 et: 
  3  ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ## 
  4  # 
  5  #   See COPYING file distributed along with the PyMVPA package for the 
  6  #   copyright and license terms. 
  7  # 
  8  ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ### ## 
  9  """Verbose output and debugging facility 
 10   
 11  Examples: 
 12  from verbosity import verbose, debug; debug.active = [1,2,3]; debug(1, "blah") 
 13   
 14  """ 
 15   
 16  __docformat__ = 'restructuredtext' 
 17   
 18  from sys import stdout, stderr 
 19  from sets import Set 
 20  # GOALS 
 21  #  any logger should be able 
 22  #   to log into a file or stdout/stderr 
 23  #   provide ability to log with/without a new line at the end 
 24  # 
 25  #  debug logger should be able 
 26  #    to log sets of debug statements 
 27  #    add/remove debug setid items 
 28  #    give verbose description about registered debugset items 
 29   
30 -class Logger(object):
31 """ 32 Base class to provide logging 33 """ 34
35 - def __init__(self, handlers=None):
36 """Initialize the logger with a set of handlers to use for output 37 38 Each hanlder must have write() method implemented 39 """ 40 if handlers == None: 41 handlers = [stdout] 42 self.__close_handlers = [] 43 self._setHandlers(handlers) 44 self.__lfprev = True 45 self.__crprev = 0 # number of symbols in previous cr-ed
46
47 - def __del__(self):
49
50 - def _setHandlers(self, handlers):
51 """Set list of handlers for the log. 52 53 A handler can be opened files, stdout, stderr, or a string, which 54 will be considered a filename to be opened for writing 55 """ 56 handlers_ = [] 57 self._closeOpenedHandlers() 58 for handler in handlers: 59 if isinstance(handler, basestring): 60 try: 61 handler = {'stdout' : stdout, 62 'stderr' : stderr}[handler.lower()] 63 except: 64 try: 65 handler = open(handler, 'w') 66 self.__close_handlers.append(handler) 67 except: 68 raise RuntimeError, \ 69 "Cannot open file %s for writing by the logger" \ 70 % handler 71 handlers_.append(handler) 72 self.__handlers = handlers_
73
74 - def _closeOpenedHandlers(self):
75 """Close opened handlers (such as opened logfiles 76 """ 77 for handler in self.__close_handlers: 78 handler.close()
79
80 - def _getHandlers(self):
81 """Return active handlers 82 """ 83 return self.__handlers
84 85
86 - def __call__(self, msg, lf=True, cr=False, *args, **kwargs):
87 """ 88 Write msg to each of the handlers. 89 90 It can append a newline (lf = Line Feed) or return 91 to the beginning before output and to take care about 92 cleaning previous message if present 93 94 it appends a newline (lf = Line Feed) since most commonly each 95 call is a separate message 96 """ 97 if kwargs.has_key('msgargs'): 98 msg = msg % kwargs['msgargs'] 99 100 if cr: 101 msg_ = "" 102 if self.__crprev > 0: 103 # wipe out older line to make sure to see no ghosts 104 msg_ = "\r%s\r" % (" "*self.__crprev) 105 msg_ += msg 106 self.__crprev = len(msg) 107 msg = msg_ 108 # since it makes no sense this days for cr and lf, 109 # override lf 110 lf = False 111 else: 112 self.__crprev += len(msg) 113 114 if lf: 115 msg = msg + "\n" 116 self.__crprev = 0 # nothing to clear 117 118 for handler in self.__handlers: 119 handler.write(msg) 120 try: 121 handler.flush() 122 except: 123 # it might be not implemented.. 124 pass 125 126 self.__lfprev = lf
127 128 handlers = property(fget=_getHandlers, fset=_setHandlers) 129 lfprev = property(fget=lambda self:self.__lfprev)
130 131 132
133 -class LevelLogger(Logger):
134 """ 135 Logger which prints based on level -- ie everything which is smaller 136 than specified level 137 """ 138
139 - def __init__(self, level=0, indent=" ", *args, **kwargs):
140 """Define level logger. 141 142 It is defined by 143 `level`, int: to which messages are reported 144 `indent`, string: symbol used to indent 145 """ 146 Logger.__init__(self, *args, **kwargs) 147 self.__level = level # damn pylint ;-) 148 self.__indent = indent 149 self._setLevel(level) 150 self._setIndent(indent)
151
152 - def _setLevel(self, level):
153 """Set logging level 154 """ 155 ilevel = int(level) 156 if ilevel < 0: 157 raise ValueError, \ 158 "Negative verbosity levels (got %d) are not supported" \ 159 % ilevel 160 self.__level = ilevel
161 162
163 - def _setIndent(self, indent):
164 """Either to indent the lines based on message log level""" 165 self.__indent = "%s" % indent
166 167
168 - def __call__(self, level, msg, *args, **kwargs):
169 """ 170 Write msg and indent using self.indent it if it was requested 171 172 it appends a newline since most commonly each call is a separate 173 message 174 """ 175 if level <= self.level: 176 if self.lfprev and self.indent: 177 # indent if previous line ended with newline 178 msg = self.indent*level + msg 179 Logger.__call__(self, msg, *args, **kwargs)
180 181 level = property(fget=lambda self: self.__level, fset=_setLevel) 182 indent = property(fget=lambda self: self.__indent, fset=_setIndent)
183 184
185 -class OnceLogger(Logger):
186 """ 187 Logger which prints a message for a given ID just once. 188 189 It could be used for one-time warning to don't overfill the output 190 with useless repeatative messages 191 """ 192
193 - def __init__(self, *args, **kwargs):
194 """Define once logger. 195 """ 196 Logger.__init__(self, *args, **kwargs) 197 self._known = {}
198 199
200 - def __call__(self, ident, msg, count=1, *args, **kwargs):
201 """ 202 Write `msg` if `ident` occured less than `count` times by now. 203 """ 204 if not self._known.has_key(ident): 205 self._known[ident] = 0 206 207 if count < 0 or self._known[ident] < count: 208 self._known[ident] += 1 209 Logger.__call__(self, msg, *args, **kwargs)
210 211
212 -class SetLogger(Logger):
213 """ 214 Logger which prints based on defined sets identified by Id. 215 """ 216
217 - def __init__(self, register=None, active=None, printsetid=True, 218 *args, **kwargs):
219 if register == None: 220 register = {} 221 if active == None: 222 active = [] 223 Logger.__init__(self, *args, **kwargs) 224 self.__printsetid = printsetid 225 self.__registered = register # all "registered" sets descriptions 226 # which to output... pointless since __registered 227 self._setActive(active) 228 self._setPrintsetid(printsetid)
229 230
231 - def _setActive(self, active):
232 """Set active logging set 233 """ 234 # just unique entries... we could have simply stored Set I guess, 235 # but then smth like debug.active += ["BLAH"] would not work 236 from mvpa.misc import verbose 237 self.__active = [] 238 registered_keys = self.__registered.keys() 239 for item in list(Set(active)): 240 if item == '': 241 continue 242 if isinstance(item, basestring): 243 if item.upper() == "ALL": 244 verbose(2, "Enabling all registered debug handlers") 245 self.__active = registered_keys 246 break 247 # try to match item as it is regexp 248 regexp = re.compile("^%s$" % item) 249 matching_keys = filter(regexp.match, registered_keys) 250 self.__active += matching_keys 251 else: 252 self.__active.append(item) 253 254 self.__active = list(Set(self.__active)) # select just unique ones 255 self.__maxstrlength = max([len(str(x)) for x in self.__active] + [0]) 256 if len(self.__active): 257 verbose(2, "Enabling debug handlers: %s" % `self.__active`)
258 259
260 - def _setPrintsetid(self, printsetid):
261 """Either to print set Id at each line""" 262 self.__printsetid = printsetid
263 264
265 - def __call__(self, setid, msg, *args, **kwargs):
266 """ 267 Write msg 268 269 It appends a newline since most commonly each call is a separate 270 message 271 """ 272 if not self.__registered.has_key(setid): 273 self.__registered[setid] = "No Description" 274 275 if setid in self.__active: 276 if self.__printsetid: 277 msg = "[%%-%ds] " % self.__maxstrlength % (setid) + msg 278 Logger.__call__(self, msg, *args, **kwargs)
279 280
281 - def register(self, setid, description):
282 """ "Register" a new setid with a given description for easy finding 283 """ 284 285 if self.__registered.has_key(setid): 286 raise ValueError, \ 287 "Setid %s is already known with description '%s'" % \ 288 ( `setid`, self.__registered[setid] ) 289 self.__registered[setid] = description
290 291
292 - def setActiveFromString(self, value):
293 """Given a string listing registered(?) setids, make then active 294 """ 295 # somewhat evil but works since verbose must be initiated 296 # by now 297 self.active = value.split(",")
298 299 300 printsetid = property(fget=lambda self: self.__printsetid, \ 301 fset=_setPrintsetid) 302 active = property(fget=lambda self: self.__active, fset=_setActive) 303 registered = property(fget=lambda self: self.__registered)
304 305 306 if __debug__: 307 308 import os, re 309 import traceback 310 import time 311
312 - def parseStatus(field='VmSize'):
313 """Return stat information on current process. 314 315 Usually it is needed to know where the memory is gone, that is 316 why VmSize is the default for the field to spit out 317 TODO: Spit out multiple fields. Use some better way than parsing proc 318 """ 319 320 fd = open('/proc/%d/status'%os.getpid()) 321 lines = fd.readlines() 322 fd.close() 323 return filter(lambda x:re.match('^%s:'%field, x), lines)[0].strip()
324 325
326 - class RelativeTime(object):
327 """Simple helper class to provide relative time it took from previous 328 invocation""" 329
330 - def __init__(self, format="%3.3f sec"):
331 self.__prev = None 332 self.__format = format
333
334 - def __call__(self):
335 dt = 0.0 336 ct = time.time() 337 if not self.__prev is None: 338 dt = ct - self.__prev 339 self.__prev = ct 340 return self.__format % dt
341 342
343 - class DebugLogger(SetLogger):
344 """ 345 Logger for debugging purposes. 346 347 Expands SetLogger with ability to print some interesting information 348 (named Metric... XXX) about current process at each debug printout 349 """ 350 351 _known_metrics = { 352 'vmem' : lambda : parseStatus(field='VmSize'), 353 'pid' : lambda : parseStatus(field='Pid'), 354 'asctime' : time.asctime 355 } 356 357
358 - def __init__(self, metrics=None, offsetbydepth=True, *args, **kwargs):
359 if metrics == None: 360 metrics = [] 361 SetLogger.__init__(self, *args, **kwargs) 362 self.__metrics = [] 363 self._offsetbydepth = offsetbydepth 364 self._reltimer = RelativeTime() 365 self._known_metrics = DebugLogger._known_metrics 366 self._known_metrics['reltime'] = self._reltimer 367 for metric in metrics: 368 self._registerMetric(metric)
369 370
371 - def registerMetric(self, func):
372 """Register some metric to report 373 374 func can be either a function call or a string which should 375 correspond to known metrics 376 """ 377 378 if isinstance(func, basestring): 379 if func in ['all', 'ALL']: 380 func = self._known_metrics.keys() 381 382 if isinstance(func, basestring): 383 if DebugLogger._known_metrics.has_key(func): 384 func = DebugLogger._known_metrics[func] 385 else: 386 raise ValueError, \ 387 "Unknown name %s for metric in DebugLogger" % \ 388 func + " Known metrics are " + \ 389 `DebugLogger._known_metrics.keys()` 390 elif isinstance(func, list): 391 for item in func: 392 self.registerMetric(item) 393 return 394 395 if not func in self.__metrics: 396 try: 397 from mvpa.misc import debug 398 debug("DBG", "Registering metric %s" % func) 399 self.__metrics.append(func) 400 except: 401 pass
402 403
404 - def __call__(self, setid, msg, *args, **kwargs):
405 if not setid in self.active: 406 # don't even compute the metrics, since they might 407 # be statefull as RelativeTime 408 return 409 410 msg_ = "" 411 412 for metric in self.__metrics: 413 msg_ += " %s" % `metric()` 414 415 if len(msg_)>0: 416 msg_ = "{%s}" % msg_ 417 418 # determine blank offset using backstacktrace 419 if self._offsetbydepth: 420 level = len(traceback.extract_stack())-2 421 else: 422 level = 1 423 424 SetLogger.__call__(self, setid, "DBG%s:%s%s" % 425 (msg_, " "*level, msg), 426 *args, **kwargs)
427 428
429 - def _setOffsetByDepth(self, b):
430 self._offsetbydepth = b
431 432 offsetbydepth = property(fget=lambda x:x._offsetbydepth, 433 fset=_setOffsetByDepth)
434