Demonstrates apparent latency with logging that is below the desired level

logging_latency.py

# Run from bin/pycc using the %run magic command
# %run logging_latency.py

if __name__ == '__main__':    
    import time
    from ooi.logging import log
    
    # Using the base logging.yml, no logging.local.yml
    # So we're set to logging of INFO
    print 'Check that we\'re at the expected logging level\n'
    print 'Info should come out:'
    log.info('hi')
    
    print '\nDebug should NOT come out:'
    log.debug('hi')
    
    print '\nPerform some tests - time a simple loop; once with logging, once with logging commented'
    
    rep_set = [100, 1000, 10000, 100000, 1000000]
    
    print '#Reps\tlog\tno-log'
    for r in rep_set:
        st=time.time()
        for x in xrange(r):
            var=str(x)
            log.debug(var)
        wlog = time.time() - st
    
        st = time.time()
        for x in xrange(r):
            var=str(x)
            #log.debug(var)
        nlog = time.time() - st
        
        print '%s\t%s\t%s' % (r, wlog, nlog)