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

Last change on this file since 8279 was 8279, checked in by neweyv, 11 years ago

Additional information written to the log file. This information will assist in creating an algorithm to predict the runtime of ANUGA given various parameters.

  • Property svn:executable set to *
File size: 13.0 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
297
298def resource_usage_timing(level=logging.INFO, prefix =""):
299    '''Log memory usage at given log level.'''
300
301    _scale = {'KB': 1024, 'MB': 1024*1024, 'GB': 1024*1024*1024,
302              'kB': 1024, 'mB': 1024*1024, 'gB': 1024*1024*1024}
303
304    if sys.platform != 'win32':
305        _proc_status = '/proc/%d/status' % os.getpid()
306       
307        def _VmB(VmKey):
308            '''Get number of virtual bytes used.'''
309
310            # get pseudo file /proc/<pid>/status
311            try:
312                t = open(_proc_status)
313                v = t.read()
314                t.close()
315            except IOError:
316                return 0.0
317
318            # get VmKey line, eg: 'VmRSS: 999 kB\n ...
319            i = v.index(VmKey)
320            v = v[i:].split(None, 3)
321            if len(v) < 3:
322                return 0.0
323
324            # convert Vm value to bytes
325            return float(v[1]) * _scale[v[2]]
326
327        def memory(since=0.0):
328            '''Get virtual memory usage in bytes.'''
329
330            return _VmB('VmSize:') - since
331
332        def resident(since=0.0):
333            '''Get resident memory usage in bytes.'''
334
335            return _VmB('VmRSS:') - since
336
337        def stacksize(since=0.0):
338            '''Get stack size in bytes.'''
339
340            return _VmB('VmStk:') - since
341
342        msg = ('Resource usage: memory=%.1fMB resident=%.1fMB stacksize=%.1fMB'
343               % (memory()/_scale['MB'], resident()/_scale['MB'],
344                  stacksize()/_scale['MB']))
345        log(msg, level)
346        timingInfo('sys_platform, ' + sys.platform)
347        timingInfo(prefix + 'memory, ' + str(memory()/_scale['MB']))
348        timingInfo(prefix + 'resident, ' + str(resident()/_scale['MB']))
349        timingInfo(prefix + 'stacksize, ' + str(stacksize()/_scale['MB']))
350    else:
351        # Windows code from: http://code.activestate.com/recipes/511491/
352        try:
353            import ctypes
354            import _winreg
355        except:
356            log(level, 'Windows resource usage not available')
357            return
358
359        kernel32 = ctypes.windll.kernel32
360        c_ulong = ctypes.c_ulong
361        c_ulonglong = ctypes.c_ulonglong
362        class MEMORYSTATUSEX(ctypes.Structure):
363            _fields_ = [('dwLength', c_ulong),
364                        ('dwMemoryLoad', c_ulong),
365                        ('ullTotalPhys', c_ulonglong),
366                        ('ullAvailPhys', c_ulonglong),
367                        ('ullTotalPageFile', c_ulonglong),
368                        ('ullAvailPageFile', c_ulonglong),
369                        ('ullTotalVirtual', c_ulonglong),
370                        ('ullAvailVirtual', c_ulonglong),
371                        ('ullAvailExtendedVirtual', c_ulonglong)
372                       ]
373
374        memoryStatusEx = MEMORYSTATUSEX()
375        memoryStatusEx.dwLength = ctypes.sizeof(MEMORYSTATUSEX)
376        kernel32.GlobalMemoryStatusEx(ctypes.byref(memoryStatusEx))
377
378        msg = ('Resource usage: total memory=%.1fMB free memory=%.1fMB'
379               % (memoryStatusEx.ullTotalPhys/_scale['MB'],
380                  memoryStatusEx.ullAvailPhys/_scale['MB']))
381        log(msg, level)
382        timingInfo('sys_platform, ' + sys.platform)
383        timingInfo(prefix + 'total_memory, ' + str(memoryStatusEx.ullTotalPhys/_scale['MB']))
384        timingInfo(prefix + 'free_memory, ' + str(memoryStatusEx.ullAvailPhys/_scale['MB']))
385
386   
387################################################################################
388if __name__ == '__main__':
389    critical('#' * 80)
390    warning('Test of logging...')
391    log('CRITICAL+1', CRITICAL+1)
392    log('CRITICAL', CRITICAL)
393    log('CRITICAL-1', CRITICAL-1)
394    log('CRITICAL-2', CRITICAL-2)
395    log('default - CRITICAL?')
396
397    def test_it(num=100):
398        if num > 0:
399            test_it(num-1)
400        else:
401            resource_usage()
402
403    import numpy as num
404   
405    a = num.zeros((1000,1000), num.float)
406
407    info('sys.version_info=%s, _new_python=%s'
408         % (str(sys.version_info), str(_new_python)))
409    test_it()
Note: See TracBrowser for help on using the repository browser.