{ "cells": [ { "cell_type": "markdown", "id": "649dc731", "metadata": {}, "source": [ "# Thread debugging\n", "\n", "This notebook shows a logging mechanism which allows to more easily debug multithreaded code in Python.\n", "\n", "Each thread can create a printer:\n", "```python\n", "# thread 1\n", "p = printer(1)\n", "p(\"hello\")\n", "p.sleep(1, \"thinking\")\n", "p.rsleep(1, \"eating\")\n", "\n", "# thread 2\n", "p = printer(2)\n", "p(\"hi there\")\n", "p.rsleep(1, \"thinking\")\n", "p.sleep(1, \"eating\")\n", "```\n", "Output:\n", "```text\n", "10:20:18.045: [t1] hello\n", "10:20:18.046: [t1] Sleep 1.00s -- thinking\n", "10:20:19.052: [t1] Sleep 0.13s -- eating\n", "10:20:19.193: [t2] hi there\n", "10:20:19.195: [t2] Sleep 0.99s -- thinking\n", "10:20:20.183: [t2] Sleep 1.00s -- eating\n", "```\n", "\n", "## Functionality\n", "The printer can do three things:\n", "- `print` exactly like the `print()` function in Python.\n", "- `print.sleep(duration, args)`. Sleeps for a set duration and prints `args`.\n", "- `print.rsleep(duration, args)`. Same as above, but sleeps for a random duration between 0 and `duration`.\n", "\n", "### Printer library code:" ] }, { "cell_type": "code", "execution_count": 1, "id": "db288024", "metadata": {}, "outputs": [], "source": [ "import logging\n", "import time\n", "import random\n", "\n", "def _getlogger():\n", " logger = logging.getLogger(__name__)\n", " logger.setLevel(logging.INFO)\n", "\n", " ch = logging.StreamHandler()\n", " ch.setLevel(logging.INFO)\n", "\n", " formatter = logging.Formatter('%(asctime)s.%(msecs)03d: %(message)s', '%H:%M:%S')\n", " ch.setFormatter(formatter)\n", " logger.addHandler(ch)\n", " return logger\n", "\n", "logger = _getlogger()\n", "\n", "def _print_line(thread_index, s):\n", " prefix = ' ' * (thread_index - 1) * 30\n", " t = '[t' + str(thread_index) + ']'\n", "\n", " logger.info(prefix + t + \" \" + s)\n", "\n", "def _sleep(ti, *args):\n", " sleep_time = args[0]\n", " sleep_message = ''\n", " if len(args) > 1:\n", " sleep_message = ' -- ' + ' '.join(str(arg) for arg in args[1:])\n", "\n", " _print_line(ti, f\"Sleep {sleep_time:.2f}s{sleep_message}\")\n", " time.sleep(sleep_time)\n", "\n", "def _random_sleep(ti, *args):\n", " rand_sleep_duration = random.random() * args[0]\n", " args = (rand_sleep_duration,) + args[1:]\n", " _sleep(ti, *args)\n", "\n", "def printer(thread_index):\n", " def custom_print(*args):\n", " args_str = ' '.join(str(arg) for arg in args)\n", " _print_line(thread_index, args_str)\n", "\n", " custom_print.sleep = lambda *args: _sleep(thread_index, *args)\n", " custom_print.rsleep = lambda *args: _random_sleep(thread_index, *args)\n", " return custom_print" ] }, { "cell_type": "markdown", "id": "ca4ae185", "metadata": {}, "source": [ "### Simple example" ] }, { "cell_type": "code", "execution_count": 2, "id": "a272d6bf", "metadata": {}, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "10:20:18.045: [t1] hello\n", "10:20:18.046: [t1] Sleep 1.00s -- thinking\n", "10:20:19.052: [t1] Sleep 0.13s -- eating\n", "10:20:19.193: [t2] hi there\n", "10:20:19.195: [t2] Sleep 0.99s -- thinking\n", "10:20:20.183: [t2] Sleep 1.00s -- eating\n" ] } ], "source": [ "p = printer(1)\n", "p(\"hello\")\n", "p.sleep(1, \"thinking\")\n", "p.rsleep(1, \"eating\")\n", "\n", "p = printer(2)\n", "p(\"hi there\")\n", "p.rsleep(1, \"thinking\")\n", "p.sleep(1, \"eating\")" ] }, { "cell_type": "markdown", "id": "7305e8a2", "metadata": {}, "source": [ "### Example with threads" ] }, { "cell_type": "code", "execution_count": 4, "id": "8f86495d", "metadata": { "scrolled": true }, "outputs": [ { "name": "stderr", "output_type": "stream", "text": [ "10:21:52.067: [t1] Sleep 0.59s -- work\n", "10:21:52.068: [t2] Sleep 1.21s -- work\n", "10:21:52.068: [t3] Sleep 0.08s -- work\n", "10:21:52.156: [t3] work is done\n", "10:21:52.158: [t3] Sleep 0.31s -- work\n", "10:21:52.477: [t3] work is done\n", "10:21:52.479: [t3] Sleep 1.01s -- work\n", "10:21:52.662: [t1] work is done\n", "10:21:52.664: [t1] Sleep 0.63s -- work\n", "10:21:53.284: [t2] work is done\n", "10:21:53.286: [t2] Sleep 0.76s -- work\n", "10:21:53.299: [t1] work is done\n", "10:21:53.301: [t1] Sleep 0.62s -- work\n", "10:21:53.500: [t3] work is done\n", "10:21:53.503: [t3] Sleep 1.32s -- work\n", "10:21:53.928: [t1] work is done\n", "10:21:53.930: [t1] Sleep 0.57s -- work\n", "10:21:54.045: [t2] work is done\n", "10:21:54.047: [t2] Sleep 0.79s -- work\n", "10:21:54.501: [t1] work is done\n", "10:21:54.503: [t1] Sleep 1.24s -- work\n", "10:21:54.820: [t3] work is done\n", "10:21:54.822: [t3] Sleep 1.35s -- work\n", "10:21:54.838: [t2] work is done\n", "10:21:54.839: [t2] Sleep 0.64s -- work\n", "10:21:55.483: [t2] work is done\n", "10:21:55.485: [t2] Sleep 0.60s -- work\n", "10:21:55.744: [t1] work is done\n", "10:21:55.746: [t1] Sleep 0.52s -- work\n", "10:21:56.088: [t2] work is done\n", "10:21:56.090: [t2] Sleep 0.96s -- work\n", "10:21:56.179: [t3] work is done\n", "10:21:56.180: [t3] Sleep 1.36s -- work\n", "10:21:56.272: [t1] work is done\n", "10:21:57.058: [t2] work is done\n", "10:21:57.541: [t3] work is done\n" ] } ], "source": [ "import threading\n", "import time\n", "import queue\n", "import common\n", "import random\n", "\n", "\n", "def worker(thread_index):\n", " print = printer(thread_index)\n", "\n", " for i in range(6):\n", " print.rsleep(1.5, \"work\")\n", " print(\"work is done\")\n", "\n", "threads = [threading.Thread(target=worker, args=(index,)) for index in range(1,4)]\n", "\n", "for t in threads:\n", " t.start()\n", "for t in threads:\n", " t.join()\n", "\n" ] }, { "cell_type": "code", "execution_count": null, "id": "c4d208f0", "metadata": {}, "outputs": [], "source": [] } ], "metadata": { "kernelspec": { "display_name": "Python 3 (ipykernel)", "language": "python", "name": "python3" }, "language_info": { "codemirror_mode": { "name": "ipython", "version": 3 }, "file_extension": ".py", "mimetype": "text/x-python", "name": "python", "nbconvert_exporter": "python", "pygments_lexer": "ipython3", "version": "3.9.6" } }, "nbformat": 4, "nbformat_minor": 5 }