source: trunk/anuga_core/source/anuga/utilities/log.py @ 8843

Last change on this file since 8843 was 8427, checked in by davies, 13 years ago

Adding the trapezoidal channel validation test, and editing the ANUGA manual
File size: 13.1 KB
Line 
1#!/usr/bin/env python
2
3'''
4A simple logging module that logs to the console and a logfile, and has a
5configurable threshold loglevel for each of console and logfile output.
6
7Use it this way:
8    import anuga.utilities.log as log
9
10    # configure my logging
11    log.console_logging_level = log.INFO
12    log.log_logging_level = log.DEBUG
13    log.log_filename = './my.log'
14
15    # log away!
16    log.debug('A message at DEBUG level')
17    log.info('Another message, INFO level')
18
19This class uses the 'borg' pattern - there is never more than one instance
20of log data.  See the URL for the basic idea used here: modules *are*
21singletons!
22
23<http://www.suttoncourtenay.org.uk/duncan/accu/pythonpatterns.html>
24
25Until the first call to log() the user is free to play with the module data
26to configure the logging.
27
28Note that this module uses some features of the logging package that were
29introduced in python2.5.  If running on earlier versions, the following
30features are disabled:
31    . Calling module name + line number
32'''
33
34import os
35import sys
36import traceback
37import logging
38import datetime
39
40DefaultConsoleLogLevel = logging.CRITICAL
41DefaultFileLogLevel = logging.INFO
42TimingDelimiter ='#@# '
43
44################################################################################
45# Module variables - only one copy of these, ever.
46#
47# The console logging level is set to a high level, like CRITICAL.  The logfile
48# logging is set lower, between DEBUG and CRITICAL.  The idea is to log least to
49# the console, but ensure that everything that goes to the console *will* also
50# appear in the log file.  There is code to ensure log <= console levels.
51#
52# If console logging level is set to CRITICAL+1 then nothing will print on the
53# console.
54################################################################################
55
56# flag variable to determine if logging set up or not
57_setup = False
58
59# logging level for the console
60console_logging_level = DefaultConsoleLogLevel
61
62# logging level for the logfile
63log_logging_level = DefaultFileLogLevel
64
65# The default name of the file to log to.
66log_filename = os.path.join('.', 'anuga.log')
67
68# set module variables so users don't have to do 'import logging'.
69CRITICAL = logging.CRITICAL
70ERROR = logging.ERROR
71WARNING = logging.WARNING
72INFO = logging.INFO
73DEBUG = logging.DEBUG
74NOTSET = logging.NOTSET
75
76# set _new_python to True if python version 2.5 or later
77_new_python = (sys.version_info[0]*10 + sys.version_info[1] >= 25)      # 2.5.x.x
78
79
80################################################################################
81# Module code.
82################################################################################
83
84def log(msg, level=None):
85    '''Log a message at a particular loglevel.
86
87    msg:    The message string to log.
88    level:  The logging level to log with (defaults to console level).
89
90    The first call to this method (by anybody) initializes logging and
91    then logs the message.  Subsequent calls just log the message.
92    '''
93
94    global _setup, log_logging_level
95    fname = '' # default to no frame name if it cannot be found
96    lnum = 0
97
98    # have we been setup?
99    if not _setup:
100        # sanity check the logging levels, require console >= file
101        if log_logging_level > console_logging_level:
102            log_logging_level = console_logging_level
103
104        # setup the file logging system
105        if _new_python:
106            fmt = '%(asctime)s %(levelname)-8s %(mname)25s:%(lnum)-4d|%(message)s'
107        else:
108            fmt = '%(asctime)s %(levelname)-8s|%(message)s'
109        logging.basicConfig(level=log_logging_level, format=fmt,
110                            filename=log_filename, filemode='w')
111
112        # define a console handler which writes to sys.stdout
113        console = logging.StreamHandler(sys.stdout)
114        console.setLevel(console_logging_level)
115        formatter = logging.Formatter('%(message)s')
116        console.setFormatter(formatter)
117        logging.getLogger('').addHandler(console)
118
119        # catch exceptions
120        sys.excepthook = log_exception_hook
121
122        # tell the world how we are set up
123        start_msg = ("Logfile is '%s' with logging level of %s, "
124                     "console logging level is %s"
125                     % (log_filename,
126                        logging.getLevelName(log_logging_level),
127                        logging.getLevelName(console_logging_level)))
128        if _new_python:
129            logging.log(logging.INFO, start_msg,
130                        extra={'mname': __name__, 'lnum': 0})
131        else:
132            logging.log(logging.INFO, start_msg)
133
134        # mark module as *setup*
135        _setup = True
136
137    # if logging level not supplied, assume console level
138    if level is None:
139        level = console_logging_level
140
141    # get caller information - look back for first module != <this module name>
142    frames = traceback.extract_stack()
143    frames.reverse()
144    try:
145        (_, mod_name) = __name__.rsplit('.', 1)
146    except ValueError:
147        mod_name = __name__
148    for (fpath, lnum, mname, _) in frames:
149        (fname, _) = os.path.basename(fpath).rsplit('.', 1)
150        if fname != mod_name:
151            break
152
153    # why are we here? ... Oh yes! Log the message!
154    if _new_python:
155        logging.log(level, msg, extra={'mname': fname, 'lnum': lnum})
156    else:
157        logging.log(level, msg)
158
159
160def log_exception_hook(type, value, tb):
161    '''Hook function to process uncaught exceptions.
162
163    type:   Type of exception.
164    value:  The exception data.
165    tb:     Traceback object.
166
167    This has the same interface as sys.excepthook().
168    '''
169
170    msg = '\n' + ''.join(traceback.format_exception(type, value, tb))
171    critical(msg)
172
173   
174################################################################################
175# Shortcut routines to make for simpler user code.
176################################################################################
177
178def debug(msg=''):
179    '''Shortcut for log(DEBUG, msg).'''
180
181    log(msg, logging.DEBUG)
182
183
184def info(msg=''):
185    '''Shortcut for log(INFO, msg).'''
186
187    log(msg, logging.INFO)
188
189
190def warning(msg=''):
191    '''Shortcut for log(WARNING, msg).'''
192
193    log(msg, logging.WARNING)
194
195
196def error(msg=''):
197    '''Shortcut for log(ERROR, msg).'''
198
199    log(msg, logging.ERROR)
200
201
202def critical(msg=''):
203    '''Shortcut for log(CRITICAL, msg).'''
204
205    log(msg, logging.CRITICAL)
206
207def timingInfo(msg=''):
208    '''Shortcut for log(timingDelimiter, msg).'''
209
210    log(TimingDelimiter + msg, logging.INFO)
211
212
213def resource_usage(level=logging.INFO):
214    '''Log memory usage at given log level.'''
215
216    _scale = {'KB': 1024, 'MB': 1024*1024, 'GB': 1024*1024*1024,
217              'kB': 1024, 'mB': 1024*1024, 'gB': 1024*1024*1024}
218
219    if sys.platform != 'win32':
220        _proc_status = '/proc/%d/status' % os.getpid()
221       
222        def _VmB(VmKey):
223            '''Get number of virtual bytes used.'''
224
225            # get pseudo file /proc/<pid>/status
226            try:
227                t = open(_proc_status)
228                v = t.read()
229                t.close()
230            except IOError:
231                return 0.0
232
233            # get VmKey line, eg: 'VmRSS: 999 kB\n ...
234            i = v.index(VmKey)
235            v = v[i:].split(None, 3)
236            if len(v) < 3:
237                return 0.0
238
239            # convert Vm value to bytes
240            return float(v[1]) * _scale[v[2]]
241
242        def memory(since=0.0):
243            '''Get virtual memory usage in bytes.'''
244
245            return _VmB('VmSize:') - since
246
247        def resident(since=0.0):
248            '''Get resident memory usage in bytes.'''
249
250            return _VmB('VmRSS:') - since
251
252        def stacksize(since=0.0):
253            '''Get stack size in bytes.'''
254
255            return _VmB('VmStk:') - since
256
257        msg = ('Resource usage: memory=%.1fMB resident=%.1fMB stacksize=%.1fMB'
258               % (memory()/_scale['MB'], resident()/_scale['MB'],
259                  stacksize()/_scale['MB']))
260        log(msg, level)
261    else:
262        # Windows code from: http://code.activestate.com/recipes/511491/
263        try:
264            import ctypes
265            import _winreg
266        except:
267            log(level, 'Windows resource usage not available')
268            return
269
270        kernel32 = ctypes.windll.kernel32
271        c_ulong = ctypes.c_ulong
272        c_ulonglong = ctypes.c_ulonglong
273        class MEMORYSTATUSEX(ctypes.Structure):
274            _fields_ = [('dwLength', c_ulong),
275                        ('dwMemoryLoad', c_ulong),
276                        ('ullTotalPhys', c_ulonglong),
277                        ('ullAvailPhys', c_ulonglong),
278                        ('ullTotalPageFile', c_ulonglong),
279                        ('ullAvailPageFile', c_ulonglong),
280                        ('ullTotalVirtual', c_ulonglong),
281                        ('ullAvailVirtual', c_ulonglong),
282                        ('ullAvailExtendedVirtual', c_ulonglong)
283                       ]
284
285        memoryStatusEx = MEMORYSTATUSEX()
286        memoryStatusEx.dwLength = ctypes.sizeof(MEMORYSTATUSEX)
287        kernel32.GlobalMemoryStatusEx(ctypes.byref(memoryStatusEx))
288
289        msg = ('Resource usage: total memory=%.1fMB free memory=%.1fMB'
290               % (memoryStatusEx.ullTotalPhys/_scale['MB'],
291                  memoryStatusEx.ullAvailPhys/_scale['MB']))
292        log(msg, level)
293
294def CurrentDateTime():
295    return datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")
296
297def TimeStamp():
298    return datetime.datetime.now().strftime('%Y%m%d_%H%M%S')
299
300
301def resource_usage_timing(level=logging.INFO, prefix =""):
302    '''Log memory usage at given log level.'''
303
304    _scale = {'KB': 1024, 'MB': 1024*1024, 'GB': 1024*1024*1024,
305              'kB': 1024, 'mB': 1024*1024, 'gB': 1024*1024*1024}
306
307    if sys.platform != 'win32':
308        _proc_status = '/proc/%d/status' % os.getpid()
309       
310        def _VmB(VmKey):
311            '''Get number of virtual bytes used.'''
312
313            # get pseudo file /proc/<pid>/status
314            try:
315                t = open(_proc_status)
316                v = t.read()
317                t.close()
318            except IOError:
319                return 0.0
320
321            # get VmKey line, eg: 'VmRSS: 999 kB\n ...
322            i = v.index(VmKey)
323            v = v[i:].split(None, 3)
324            if len(v) < 3:
325                return 0.0
326
327            # convert Vm value to bytes
328            return float(v[1]) * _scale[v[2]]
329
330        def memory(since=0.0):
331            '''Get virtual memory usage in bytes.'''
332
333            return _VmB('VmSize:') - since
334
335        def resident(since=0.0):
336            '''Get resident memory usage in bytes.'''
337
338            return _VmB('VmRSS:') - since
339
340        def stacksize(since=0.0):
341            '''Get stack size in bytes.'''
342
343            return _VmB('VmStk:') - since
344
345        msg = ('Resource usage: memory=%.1fMB resident=%.1fMB stacksize=%.1fMB'
346               % (memory()/_scale['MB'], resident()/_scale['MB'],
347                  stacksize()/_scale['MB']))
348        log(msg, level)
349        timingInfo('sys_platform, ' + sys.platform)
350        timingInfo(prefix + 'memory, ' + str(memory()/_scale['MB']))
351        timingInfo(prefix + 'resident, ' + str(resident()/_scale['MB']))
352        timingInfo(prefix + 'stacksize, ' + str(stacksize()/_scale['MB']))
353    else:
354        # Windows code from: http://code.activestate.com/recipes/511491/
355        try:
356            import ctypes
357            import _winreg
358        except:
359            log(level, 'Windows resource usage not available')
360            return
361
362        kernel32 = ctypes.windll.kernel32
363        c_ulong = ctypes.c_ulong
364        c_ulonglong = ctypes.c_ulonglong
365        class MEMORYSTATUSEX(ctypes.Structure):
366            _fields_ = [('dwLength', c_ulong),
367                        ('dwMemoryLoad', c_ulong),
368                        ('ullTotalPhys', c_ulonglong),
369                        ('ullAvailPhys', c_ulonglong),
370                        ('ullTotalPageFile', c_ulonglong),
371                        ('ullAvailPageFile', c_ulonglong),
372                        ('ullTotalVirtual', c_ulonglong),
373                        ('ullAvailVirtual', c_ulonglong),
374                        ('ullAvailExtendedVirtual', c_ulonglong)
375                       ]
376
377        memoryStatusEx = MEMORYSTATUSEX()
378        memoryStatusEx.dwLength = ctypes.sizeof(MEMORYSTATUSEX)
379        kernel32.GlobalMemoryStatusEx(ctypes.byref(memoryStatusEx))
380
381        msg = ('Resource usage: total memory=%.1fMB free memory=%.1fMB'
382               % (memoryStatusEx.ullTotalPhys/_scale['MB'],
383                  memoryStatusEx.ullAvailPhys/_scale['MB']))
384        log(msg, level)
385        timingInfo('sys_platform, ' + sys.platform)
386        timingInfo(prefix + 'total_memory, ' + str(memoryStatusEx.ullTotalPhys/_scale['MB']))
387        timingInfo(prefix + 'free_memory, ' + str(memoryStatusEx.ullAvailPhys/_scale['MB']))
388
389   
390################################################################################
391if __name__ == '__main__':
392    critical('#' * 80)
393    warning('Test of logging...')
394    log('CRITICAL+1', CRITICAL+1)
395    log('CRITICAL', CRITICAL)
396    log('CRITICAL-1', CRITICAL-1)
397    log('CRITICAL-2', CRITICAL-2)
398    log('default - CRITICAL?')
399
400    def test_it(num=100):
401        if num > 0:
402            test_it(num-1)
403        else:
404            resource_usage()
405
406    import numpy as num
407   
408    a = num.zeros((1000,1000), num.float)
409
410    info('sys.version_info=%s, _new_python=%s'
411         % (str(sys.version_info), str(_new_python)))
412    test_it()
Note: See TracBrowser for help on using the repository browser.