This notebook shows a logging mechanism which allows to more easily debug multithreaded code in Python.
Each thread can create a printer:
# thread 1
p = printer(1)
p("hello")
p.sleep(1, "thinking")
p.rsleep(1, "eating")
# thread 2
p = printer(2)
p("hi there")
p.rsleep(1, "thinking")
p.sleep(1, "eating")
Output:
10:20:18.045: [t1] hello
10:20:18.046: [t1] Sleep 1.00s -- thinking
10:20:19.052: [t1] Sleep 0.13s -- eating
10:20:19.193: [t2] hi there
10:20:19.195: [t2] Sleep 0.99s -- thinking
10:20:20.183: [t2] Sleep 1.00s -- eating
The printer can do three things:
print
exactly like the print()
function in Python.print.sleep(duration, args)
. Sleeps for a set duration and prints args
.print.rsleep(duration, args)
. Same as above, but sleeps for a random duration between 0 and duration
.import logging
import time
import random
def _getlogger():
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
ch = logging.StreamHandler()
ch.setLevel(logging.INFO)
formatter = logging.Formatter('%(asctime)s.%(msecs)03d: %(message)s', '%H:%M:%S')
ch.setFormatter(formatter)
logger.addHandler(ch)
return logger
logger = _getlogger()
def _print_line(thread_index, s):
prefix = ' ' * (thread_index - 1) * 30
t = '[t' + str(thread_index) + ']'
logger.info(prefix + t + " " + s)
def _sleep(ti, *args):
sleep_time = args[0]
sleep_message = ''
if len(args) > 1:
sleep_message = ' -- ' + ' '.join(str(arg) for arg in args[1:])
_print_line(ti, f"Sleep {sleep_time:.2f}s{sleep_message}")
time.sleep(sleep_time)
def _random_sleep(ti, *args):
rand_sleep_duration = random.random() * args[0]
args = (rand_sleep_duration,) + args[1:]
_sleep(ti, *args)
def printer(thread_index):
def custom_print(*args):
args_str = ' '.join(str(arg) for arg in args)
_print_line(thread_index, args_str)
custom_print.sleep = lambda *args: _sleep(thread_index, *args)
custom_print.rsleep = lambda *args: _random_sleep(thread_index, *args)
return custom_print
p = printer(1)
p("hello")
p.sleep(1, "thinking")
p.rsleep(1, "eating")
p = printer(2)
p("hi there")
p.rsleep(1, "thinking")
p.sleep(1, "eating")
10:20:18.045: [t1] hello 10:20:18.046: [t1] Sleep 1.00s -- thinking 10:20:19.052: [t1] Sleep 0.13s -- eating 10:20:19.193: [t2] hi there 10:20:19.195: [t2] Sleep 0.99s -- thinking 10:20:20.183: [t2] Sleep 1.00s -- eating
import threading
import time
import queue
import common
import random
def worker(thread_index):
print = printer(thread_index)
for i in range(6):
print.rsleep(1.5, "work")
print("work is done")
threads = [threading.Thread(target=worker, args=(index,)) for index in range(1,4)]
for t in threads:
t.start()
for t in threads:
t.join()
10:21:52.067: [t1] Sleep 0.59s -- work 10:21:52.068: [t2] Sleep 1.21s -- work 10:21:52.068: [t3] Sleep 0.08s -- work 10:21:52.156: [t3] work is done 10:21:52.158: [t3] Sleep 0.31s -- work 10:21:52.477: [t3] work is done 10:21:52.479: [t3] Sleep 1.01s -- work 10:21:52.662: [t1] work is done 10:21:52.664: [t1] Sleep 0.63s -- work 10:21:53.284: [t2] work is done 10:21:53.286: [t2] Sleep 0.76s -- work 10:21:53.299: [t1] work is done 10:21:53.301: [t1] Sleep 0.62s -- work 10:21:53.500: [t3] work is done 10:21:53.503: [t3] Sleep 1.32s -- work 10:21:53.928: [t1] work is done 10:21:53.930: [t1] Sleep 0.57s -- work 10:21:54.045: [t2] work is done 10:21:54.047: [t2] Sleep 0.79s -- work 10:21:54.501: [t1] work is done 10:21:54.503: [t1] Sleep 1.24s -- work 10:21:54.820: [t3] work is done 10:21:54.822: [t3] Sleep 1.35s -- work 10:21:54.838: [t2] work is done 10:21:54.839: [t2] Sleep 0.64s -- work 10:21:55.483: [t2] work is done 10:21:55.485: [t2] Sleep 0.60s -- work 10:21:55.744: [t1] work is done 10:21:55.746: [t1] Sleep 0.52s -- work 10:21:56.088: [t2] work is done 10:21:56.090: [t2] Sleep 0.96s -- work 10:21:56.179: [t3] work is done 10:21:56.180: [t3] Sleep 1.36s -- work 10:21:56.272: [t1] work is done 10:21:57.058: [t2] work is done 10:21:57.541: [t3] work is done