Skip to content

Instantly share code, notes, and snippets.

@robinovitch61

robinovitch61/race_condition.ipynb

Last active October 30, 2019 16:14
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save robinovitch61/8bf045f09ab77e26527139b914fa55d9 to your computer and use it in GitHub Desktop.
Save robinovitch61/8bf045f09ab77e26527139b914fa55d9 to your computer and use it in GitHub Desktop.
Download ZIP
race_condition.ipynb
Display the source blob
Display the rendered blob
Raw
race_condition.ipynb
{
"cells": [
{
"cell_type": "markdown",
"metadata": {},
"source": [
"# Race Conditions\n",
"***\n",
"***"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Race Condition: the system's substantive behavior is dependent on the sequence or timing of other uncontrollable events\n",
"* [From Wikipedia](https://en.wikipedia.org/wiki/Race_condition)"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"For the following example, we can forget the fact that this incrementing a counter would never be the kind of thing you would multithread for - it is not IO bound or CPU bound, and therefore performance actually degrades by threading. The counter is a simple enough concept to illustrate a race condition, though. You can think of something like reading from and writing to a database being an actual operation where threading would be relevant and comparable race conditions would be very bad."
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Setup:"
]
},
{
"cell_type": "code",
"execution_count": null,
"metadata": {},
"outputs": [],
"source": [
"import time\n",
"import logging\n",
"import threading\n",
"from concurrent.futures import ThreadPoolExecutor\n",
"\n",
"format = \"%(asctime)s | %(threadName)s: %(message)s\"\n",
"logging.basicConfig(\n",
" format=format,\n",
" level=logging.DEBUG,\n",
" datefmt=\"%M:%S\"\n",
")\n",
"\n",
"# Give a fake lock context management so can use \"with\"\n",
"class FakeLock():\n",
" def __init__(self):\n",
" self.is_fake = True\n",
"\n",
" def __enter__(self):\n",
" pass\n",
"\n",
" def __exit__(self, _, __, ___):\n",
" pass"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Create a Counter class:"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"For the first two examples, you can ignore all the stuff with the lock, as we'll be using a `FakeLock` from above by default - the lines with `self.lock` won't actually do anything."
]
},
{
"cell_type": "code",
"execution_count": null,
"metadata": {},
"outputs": [],
"source": [
"# Without logging for clarity:\n",
"class Counter():\n",
" \n",
" def __init__(self, lock=FakeLock()):\n",
" self.count = 0\n",
" self.lock = lock # by default this does nothing\n",
" self.real_lock = not hasattr(self.lock, \"is_fake\")\n",
" \n",
" def increment(self, N):\n",
" for _ in range(N):\n",
" with self.lock:\n",
" local_val = self.count\n",
" new_val = local_val + 1\n",
" time.sleep(0.01)\n",
" self.count = new_val\n",
"\n",
" def decrement(self, N):\n",
" for _ in range(N):\n",
" with self.lock:\n",
" local_val = self.count\n",
" new_val = local_val - 1\n",
" time.sleep(0.01)\n",
" self.count = new_val"
]
},
{
"cell_type": "code",
"execution_count": null,
"metadata": {},
"outputs": [],
"source": [
"# With logging, what we'll actually use\n",
"class Counter():\n",
" \n",
" def __init__(self, lock=FakeLock()):\n",
" self.count = 0\n",
" self.lock = lock # by default this does nothing\n",
" self.real_lock = not hasattr(self.lock, \"is_fake\")\n",
" \n",
" def increment(self, N):\n",
" for _ in range(N):\n",
" logging.debug(\"attempting to start increment operation\")\n",
" with self.lock:\n",
" if self.real_lock: logging.debug(\"acquired lock\")\n",
" logging.debug(\"*** START DANGER ZONE ***\")\n",
" local_val = self.count\n",
" logging.debug(f\"got local val {local_val}\")\n",
" new_val = local_val + 1\n",
" logging.debug(f\"storing incremented val {new_val} - sleeping\")\n",
" time.sleep(0.01)\n",
" logging.debug(f\"setting count to {new_val}\")\n",
" self.count = new_val\n",
" logging.debug(\"*** END DANGER ZONE ***\")\n",
" logging.debug(f\"new count is {self.count}\")\n",
" if self.real_lock: logging.debug(f\"releasing lock\")\n",
"\n",
" def decrement(self, N):\n",
" for _ in range(N):\n",
" logging.debug(\"attempting to start decrement operation\")\n",
" with self.lock:\n",
" if self.real_lock: logging.debug(\"acquired lock\")\n",
" logging.debug(\"*** START DANGER ZONE ***\")\n",
" local_val = self.count\n",
" logging.debug(f\"got local val {local_val}\")\n",
" new_val = local_val - 1\n",
" logging.debug(f\"storing decremented val {new_val} - sleeping\")\n",
" time.sleep(0.01)\n",
" logging.debug(f\"setting count to {new_val}\")\n",
" self.count = new_val\n",
" logging.debug(\"*** END DANGER ZONE ***\")\n",
" logging.debug(f\"new count is {self.count}\")\n",
" if self.real_lock: logging.debug(f\"releasing lock\")"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Single thread behaves as expected"
]
},
{
"cell_type": "code",
"execution_count": 4,
"metadata": {},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"14:30 | MainThread: setting count to 2\n",
"14:30 | MainThread: *** END DANGER ZONE ***\n",
"14:30 | MainThread: new count is 2\n",
"14:30 | MainThread: attempting to start increment operation\n",
"14:30 | MainThread: *** START DANGER ZONE ***\n",
"14:30 | MainThread: got local val 2\n",
"14:30 | MainThread: storing incremented val 3 - sleeping\n",
"14:30 | MainThread: setting count to 3\n",
"14:30 | MainThread: *** END DANGER ZONE ***\n",
"14:30 | MainThread: new count is 3\n",
"14:30 | MainThread: attempting to start decrement operation\n",
"14:30 | MainThread: *** START DANGER ZONE ***\n",
"14:30 | MainThread: got local val 3\n",
"14:30 | MainThread: storing decremented val 2 - sleeping\n",
"14:30 | MainThread: setting count to 2\n",
"14:30 | MainThread: *** END DANGER ZONE ***\n",
"14:30 | MainThread: new count is 2\n",
"14:30 | MainThread: attempting to start decrement operation\n",
"14:30 | MainThread: *** START DANGER ZONE ***\n",
"14:30 | MainThread: got local val 2\n",
"14:30 | MainThread: storing decremented val 1 - sleeping\n",
"14:30 | MainThread: setting count to 1\n",
"14:30 | MainThread: *** END DANGER ZONE ***\n",
"14:30 | MainThread: new count is 1\n",
"14:30 | MainThread: attempting to start decrement operation\n",
"14:30 | MainThread: *** START DANGER ZONE ***\n",
"14:30 | MainThread: got local val 1\n",
"14:30 | MainThread: storing decremented val 0 - sleeping\n",
"14:30 | MainThread: setting count to 0\n",
"14:30 | MainThread: *** END DANGER ZONE ***\n",
"14:30 | MainThread: new count is 0\n"
]
},
{
"name": "stdout",
"output_type": "stream",
"text": [
"Single thread ended at 0\n"
]
}
],
"source": [
"def single_thread():\n",
" counter = Counter()\n",
" counter.increment(3)\n",
" counter.decrement(3)\n",
" print(\"Single thread ended at\", counter.count)\n",
" \n",
"single_thread()"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Multi threaded approach gives wacky results!"
]
},
{
"cell_type": "code",
"execution_count": 5,
"metadata": {},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"14:30 | up: attempting to start increment operation\n",
"14:30 | \tdown: attempting to start decrement operation\n",
"14:30 | \tdown: *** START DANGER ZONE ***\n",
"14:30 | \tdown: got local val 0\n",
"14:30 | up: *** START DANGER ZONE ***\n",
"14:30 | up: got local val 0\n",
"14:30 | \tdown: storing decremented val -1 - sleeping\n",
"14:30 | up: storing incremented val 1 - sleeping\n",
"14:30 | \tdown: setting count to -1\n",
"14:30 | \tdown: *** END DANGER ZONE ***\n",
"14:30 | \tdown: new count is -1\n",
"14:30 | \tdown: attempting to start decrement operation\n",
"14:30 | \tdown: *** START DANGER ZONE ***\n",
"14:30 | \tdown: got local val -1\n",
"14:30 | \tdown: storing decremented val -2 - sleeping\n",
"14:30 | up: setting count to 1\n",
"14:30 | up: *** END DANGER ZONE ***\n",
"14:30 | up: new count is 1\n",
"14:30 | up: attempting to start increment operation\n",
"14:30 | up: *** START DANGER ZONE ***\n",
"14:30 | up: got local val 1\n",
"14:30 | up: storing incremented val 2 - sleeping\n",
"14:30 | \tdown: setting count to -2\n",
"14:30 | \tdown: *** END DANGER ZONE ***\n",
"14:30 | \tdown: new count is -2\n",
"14:30 | \tdown: attempting to start decrement operation\n",
"14:30 | \tdown: *** START DANGER ZONE ***\n",
"14:30 | \tdown: got local val -2\n",
"14:30 | \tdown: storing decremented val -3 - sleeping\n",
"14:30 | up: setting count to 2\n",
"14:30 | up: *** END DANGER ZONE ***\n",
"14:30 | up: new count is 2\n",
"14:30 | up: attempting to start increment operation\n",
"14:30 | up: *** START DANGER ZONE ***\n",
"14:30 | up: got local val 2\n",
"14:30 | up: storing incremented val 3 - sleeping\n",
"14:30 | \tdown: setting count to -3\n",
"14:30 | \tdown: *** END DANGER ZONE ***\n",
"14:30 | \tdown: new count is -3\n",
"14:30 | up: setting count to 3\n",
"14:30 | up: *** END DANGER ZONE ***\n",
"14:30 | up: new count is 3\n"
]
},
{
"name": "stdout",
"output_type": "stream",
"text": [
"Multi thread ended at 3\n"
]
}
],
"source": [
"def multi_thread():\n",
" counter = Counter()\n",
" count_up = threading.Thread(\n",
" target=counter.increment, args=(3,), name=\"up\")\n",
" count_down = threading.Thread(\n",
" target=counter.decrement, args=(3,), name=\"\\tdown\")\n",
" count_up.start()\n",
" count_down.start()\n",
" count_up.join()\n",
" count_down.join()\n",
" print(\"Multi thread ended at\", counter.count)\n",
"\n",
"multi_thread()"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"What's going on here? The calls to `time.sleep(0.01)` force the threads to change - while one thread sleeps, the threading logic decides that it's efficient to be running the other one! \n",
" \n",
"In `increment`:\n",
"```python\n",
"# make a copy of count local to the \"up\" thread\n",
"local_val = self.count\n",
"\n",
"# increment that copy\n",
"new_val = local_val + 1\n",
"\n",
"# sleep - causes switch to \"down\" thread!\n",
"time.sleep(0.01) \n",
"\n",
"# this update doesn't happen until after down thread has\n",
"# stored the non-updated value\n",
"self.count = new_val \n",
"```\n",
" \n",
"So what we end up with is `count` being set as 1 -> -1 -> 2 -> -2 -> 3 -> -3! The threads never actually transfer data to one another as sleep forces threads to switch before an operation completes."
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"You might be thinking, well, just remove the `sleep` call and it will work! This example is less contrived than you'd think, though. Because even things that seem \"atomic\" like `x += 1` actually take the processor [many individual steps](https://realpython.com/intro-to-python-threading/#why-this-isnt-a-silly-example). Threads can switch at any time, including before these steps are completed! \n",
" \n",
"This makes debugging race conditions tricky, as they may only happen 0.0001% of the time an operation is run, and therefore is difficult to replicate and pin down."
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### Using a Lock"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"Now instead of the default `FakeLock`, let's pass in a `threading.Lock` object. This is an object available to all threads and tells the processor \"while lock is acquired by thread A, threads that aren't thread A can't operate here\". Wrapping read-modify-write sections (of which even `x += 1` is one at the processor level!) in a lock ensures that threads may switch, but other threads won't operate on the locked section until the thread that originally acquired the lock completes the section and releases the lock. \n",
" \n",
"I have wrapped the read-modify-write section in \"DANGER ZONE\" printouts. Note that threads switch and happily execute read-modify-write sections before \"END DANGER ZONE\" occurs in the fake lock case above. In the actual lock case below, we'll see that threads switch, but switch back if a thread that didn't originally acquire the lock reaches a `with lock:` context. \n",
" \n",
"*Note: locks are automatically acquired at the start of `with lock:` contexts and released when the context is exited.*"
]
},
{
"cell_type": "code",
"execution_count": 6,
"metadata": {},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"14:30 | up: attempting to start increment operation\n",
"14:30 | up: acquired lock\n",
"14:30 | up: *** START DANGER ZONE ***\n",
"14:30 | up: got local val 0\n",
"14:30 | up: storing incremented val 1 - sleeping\n",
"14:30 | \tdown: attempting to start decrement operation\n",
"14:30 | up: setting count to 1\n",
"14:30 | up: *** END DANGER ZONE ***\n",
"14:30 | up: new count is 1\n",
"14:30 | up: releasing lock\n",
"14:30 | up: attempting to start increment operation\n",
"14:30 | \tdown: acquired lock\n",
"14:30 | \tdown: *** START DANGER ZONE ***\n",
"14:30 | \tdown: got local val 1\n",
"14:30 | \tdown: storing decremented val 0 - sleeping\n",
"14:30 | \tdown: setting count to 0\n",
"14:30 | \tdown: *** END DANGER ZONE ***\n",
"14:30 | \tdown: new count is 0\n",
"14:30 | \tdown: releasing lock\n",
"14:30 | \tdown: attempting to start decrement operation\n",
"14:30 | up: acquired lock\n",
"14:30 | up: *** START DANGER ZONE ***\n",
"14:30 | up: got local val 0\n",
"14:30 | up: storing incremented val 1 - sleeping\n",
"14:30 | up: setting count to 1\n",
"14:30 | up: *** END DANGER ZONE ***\n",
"14:30 | up: new count is 1\n",
"14:30 | up: releasing lock\n",
"14:30 | up: attempting to start increment operation\n",
"14:30 | \tdown: acquired lock\n",
"14:30 | \tdown: *** START DANGER ZONE ***\n",
"14:30 | \tdown: got local val 1\n",
"14:30 | \tdown: storing decremented val 0 - sleeping\n",
"14:30 | \tdown: setting count to 0\n",
"14:30 | \tdown: *** END DANGER ZONE ***\n",
"14:30 | \tdown: new count is 0\n",
"14:30 | \tdown: releasing lock\n",
"14:30 | \tdown: attempting to start decrement operation\n",
"14:30 | up: acquired lock\n",
"14:30 | up: *** START DANGER ZONE ***\n",
"14:30 | up: got local val 0\n",
"14:30 | up: storing incremented val 1 - sleeping\n",
"14:30 | up: setting count to 1\n",
"14:30 | up: *** END DANGER ZONE ***\n",
"14:30 | up: new count is 1\n",
"14:30 | up: releasing lock\n",
"14:30 | \tdown: acquired lock\n",
"14:30 | \tdown: *** START DANGER ZONE ***\n",
"14:30 | \tdown: got local val 1\n",
"14:30 | \tdown: storing decremented val 0 - sleeping\n",
"14:30 | \tdown: setting count to 0\n",
"14:30 | \tdown: *** END DANGER ZONE ***\n",
"14:30 | \tdown: new count is 0\n",
"14:30 | \tdown: releasing lock\n"
]
},
{
"name": "stdout",
"output_type": "stream",
"text": [
"Locked multi thread ended at 0\n"
]
}
],
"source": [
"def locked_multi_thread():\n",
" lock = threading.Lock()\n",
" locked_counter = Counter(lock)\n",
" \n",
" count_up = threading.Thread(\n",
" target=locked_counter.increment, args=(3,), name=\"up\")\n",
" count_down = threading.Thread(\n",
" target=locked_counter.decrement, args=(3,), name=\"\\tdown\")\n",
" \n",
" count_up.start()\n",
" count_down.start()\n",
" \n",
" count_up.join()\n",
" count_down.join()\n",
"\n",
" print(\"Locked multi thread ended at\", locked_counter.count)\n",
"\n",
"locked_multi_thread()"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"### ThreadPoolExecutor"
]
},
{
"cell_type": "markdown",
"metadata": {},
"source": [
"The same locking can be applied to more threads using `ThreadPoolExecutor`. Here 5 threads are launched, each with some combination of incrementing tasks and decrementing tasks. Because of the lock, none of these threads operate on the read-modify-write section of their functions at the same time, and behavior is as expected."
]
},
{
"cell_type": "code",
"execution_count": 7,
"metadata": {},
"outputs": [
{
"name": "stdout",
"output_type": "stream",
"text": [
"Pool locked multi thread ended at 1\n"
]
}
],
"source": [
"def pool_locked_multi_thread():\n",
" lock = threading.Lock()\n",
" locked_counter = Counter(lock)\n",
" \n",
" # after everything, counter should be 1\n",
" increments = [10, 5, 2, 9]\n",
" decrements = [9, 5, 2, 9]\n",
" with ThreadPoolExecutor(\n",
" max_workers=5, thread_name_prefix=\"pool\") as executor:\n",
" for inc in increments:\n",
" executor.submit(locked_counter.increment, inc)\n",
" for dec in decrements:\n",
" executor.submit(locked_counter.decrement, dec)\n",
"\n",
" print(\"Pool locked multi thread ended at\",\n",
" locked_counter.count)\n",
"\n",
"# No debugging to show it works:\n",
"logging.getLogger().setLevel(logging.INFO)\n",
"pool_locked_multi_thread()"
]
},
{
"cell_type": "code",
"execution_count": 8,
"metadata": {},
"outputs": [
{
"name": "stderr",
"output_type": "stream",
"text": [
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 0\n",
"14:31 | pool_0: storing incremented val 1 - sleeping\n",
"14:31 | pool_1: attempting to start increment operation\n",
"14:31 | pool_2: attempting to start increment operation\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: setting count to 1\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 1\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 1\n",
"14:31 | pool_1: storing incremented val 2 - sleeping\n",
"14:31 | pool_1: setting count to 2\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 2\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start increment operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 2\n",
"14:31 | pool_2: storing incremented val 3 - sleeping\n",
"14:31 | pool_2: setting count to 3\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 3\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_2: attempting to start increment operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 3\n",
"14:31 | pool_3: storing incremented val 4 - sleeping\n",
"14:31 | pool_3: setting count to 4\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 4\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 4\n",
"14:31 | pool_4: storing decremented val 3 - sleeping\n",
"14:31 | pool_4: setting count to 3\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 3\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 3\n",
"14:31 | pool_0: storing incremented val 4 - sleeping\n",
"14:31 | pool_0: setting count to 4\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 4\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 4\n",
"14:31 | pool_1: storing incremented val 5 - sleeping\n",
"14:31 | pool_1: setting count to 5\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 5\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start increment operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 5\n",
"14:31 | pool_2: storing incremented val 6 - sleeping\n",
"14:31 | pool_2: setting count to 6\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 6\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_2: attempting to start decrement operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 6\n",
"14:31 | pool_3: storing incremented val 7 - sleeping\n",
"14:31 | pool_3: setting count to 7\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 7\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 7\n",
"14:31 | pool_4: storing decremented val 6 - sleeping\n",
"14:31 | pool_4: setting count to 6\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 6\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 6\n",
"14:31 | pool_0: storing incremented val 7 - sleeping\n",
"14:31 | pool_0: setting count to 7\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 7\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 7\n",
"14:31 | pool_1: storing incremented val 8 - sleeping\n",
"14:31 | pool_1: setting count to 8\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 8\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start increment operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 8\n",
"14:31 | pool_2: storing decremented val 7 - sleeping\n",
"14:31 | pool_2: setting count to 7\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 7\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_2: attempting to start decrement operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 7\n",
"14:31 | pool_3: storing incremented val 8 - sleeping\n",
"14:31 | pool_3: setting count to 8\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 8\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 8\n",
"14:31 | pool_4: storing decremented val 7 - sleeping\n",
"14:31 | pool_4: setting count to 7\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 7\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 7\n",
"14:31 | pool_0: storing incremented val 8 - sleeping\n",
"14:31 | pool_0: setting count to 8\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 8\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 8\n",
"14:31 | pool_1: storing incremented val 9 - sleeping\n",
"14:31 | pool_1: setting count to 9\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 9\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start increment operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 9\n",
"14:31 | pool_2: storing decremented val 8 - sleeping\n",
"14:31 | pool_2: setting count to 8\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 8\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_2: attempting to start decrement operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 8\n",
"14:31 | pool_3: storing incremented val 9 - sleeping\n",
"14:31 | pool_3: setting count to 9\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 9\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 9\n",
"14:31 | pool_4: storing decremented val 8 - sleeping\n",
"14:31 | pool_4: setting count to 8\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 8\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 8\n",
"14:31 | pool_0: storing incremented val 9 - sleeping\n",
"14:31 | pool_0: setting count to 9\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 9\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 9\n",
"14:31 | pool_1: storing incremented val 10 - sleeping\n",
"14:31 | pool_1: setting count to 10\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 10\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start decrement operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 10\n",
"14:31 | pool_2: storing decremented val 9 - sleeping\n",
"14:31 | pool_2: setting count to 9\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 9\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_2: attempting to start decrement operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 9\n",
"14:31 | pool_3: storing incremented val 10 - sleeping\n",
"14:31 | pool_3: setting count to 10\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 10\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 10\n",
"14:31 | pool_4: storing decremented val 9 - sleeping\n",
"14:31 | pool_4: setting count to 9\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 9\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 9\n",
"14:31 | pool_0: storing incremented val 10 - sleeping\n",
"14:31 | pool_0: setting count to 10\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 10\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 10\n",
"14:31 | pool_1: storing decremented val 9 - sleeping\n",
"14:31 | pool_1: setting count to 9\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 9\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start decrement operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 9\n",
"14:31 | pool_2: storing decremented val 8 - sleeping\n",
"14:31 | pool_2: setting count to 8\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 8\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_2: attempting to start decrement operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 8\n",
"14:31 | pool_3: storing incremented val 9 - sleeping\n",
"14:31 | pool_3: setting count to 9\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 9\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 9\n",
"14:31 | pool_4: storing decremented val 8 - sleeping\n",
"14:31 | pool_4: setting count to 8\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 8\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 8\n",
"14:31 | pool_0: storing incremented val 9 - sleeping\n",
"14:31 | pool_0: setting count to 9\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 9\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 9\n",
"14:31 | pool_1: storing decremented val 8 - sleeping\n",
"14:31 | pool_1: setting count to 8\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 8\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start decrement operation\n",
"14:31 | pool_2: acquired lock\n",
"14:31 | pool_2: *** START DANGER ZONE ***\n",
"14:31 | pool_2: got local val 8\n",
"14:31 | pool_2: storing decremented val 7 - sleeping\n",
"14:31 | pool_2: setting count to 7\n",
"14:31 | pool_2: *** END DANGER ZONE ***\n",
"14:31 | pool_2: new count is 7\n",
"14:31 | pool_2: releasing lock\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 7\n",
"14:31 | pool_3: storing incremented val 8 - sleeping\n",
"14:31 | pool_3: setting count to 8\n",
"14:31 | pool_3: *** END DANGER ZONE ***\n",
"14:31 | pool_3: new count is 8\n",
"14:31 | pool_3: releasing lock\n",
"14:31 | pool_3: attempting to start increment operation\n",
"14:31 | pool_4: acquired lock\n",
"14:31 | pool_4: *** START DANGER ZONE ***\n",
"14:31 | pool_4: got local val 8\n",
"14:31 | pool_4: storing decremented val 7 - sleeping\n",
"14:31 | pool_4: setting count to 7\n",
"14:31 | pool_4: *** END DANGER ZONE ***\n",
"14:31 | pool_4: new count is 7\n",
"14:31 | pool_4: releasing lock\n",
"14:31 | pool_4: attempting to start decrement operation\n",
"14:31 | pool_0: acquired lock\n",
"14:31 | pool_0: *** START DANGER ZONE ***\n",
"14:31 | pool_0: got local val 7\n",
"14:31 | pool_0: storing incremented val 8 - sleeping\n",
"14:31 | pool_0: setting count to 8\n",
"14:31 | pool_0: *** END DANGER ZONE ***\n",
"14:31 | pool_0: new count is 8\n",
"14:31 | pool_0: releasing lock\n",
"14:31 | pool_0: attempting to start increment operation\n",
"14:31 | pool_1: acquired lock\n",
"14:31 | pool_1: *** START DANGER ZONE ***\n",
"14:31 | pool_1: got local val 8\n",
"14:31 | pool_1: storing decremented val 7 - sleeping\n",
"14:31 | pool_1: setting count to 7\n",
"14:31 | pool_1: *** END DANGER ZONE ***\n",
"14:31 | pool_1: new count is 7\n",
"14:31 | pool_1: releasing lock\n",
"14:31 | pool_1: attempting to start decrement operation\n",
"14:31 | pool_3: acquired lock\n",
"14:31 | pool_3: *** START DANGER ZONE ***\n",
"14:31 | pool_3: got local val 7\n",
"14:31 | pool_3: storing incremented val 8 - sleeping\n",
"14:32 | pool_3: setting count to 8\n",
"14:32 | pool_3: *** END DANGER ZONE ***\n",
"14:32 | pool_3: new count is 8\n",
"14:32 | pool_3: releasing lock\n",
"14:32 | pool_3: attempting to start increment operation\n",
"14:32 | pool_4: acquired lock\n",
"14:32 | pool_4: *** START DANGER ZONE ***\n",
"14:32 | pool_4: got local val 8\n",
"14:32 | pool_4: storing decremented val 7 - sleeping\n",
"14:32 | pool_4: setting count to 7\n",
"14:32 | pool_4: *** END DANGER ZONE ***\n",
"14:32 | pool_4: new count is 7\n",
"14:32 | pool_4: releasing lock\n",
"14:32 | pool_4: attempting to start decrement operation\n",
"14:32 | pool_0: acquired lock\n",
"14:32 | pool_0: *** START DANGER ZONE ***\n",
"14:32 | pool_0: got local val 7\n",
"14:32 | pool_0: storing incremented val 8 - sleeping\n",
"14:32 | pool_0: setting count to 8\n",
"14:32 | pool_0: *** END DANGER ZONE ***\n",
"14:32 | pool_0: new count is 8\n",
"14:32 | pool_0: releasing lock\n",
"14:32 | pool_0: attempting to start increment operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 8\n",
"14:32 | pool_1: storing decremented val 7 - sleeping\n",
"14:32 | pool_1: setting count to 7\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 7\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_3: acquired lock\n",
"14:32 | pool_3: *** START DANGER ZONE ***\n",
"14:32 | pool_3: got local val 7\n",
"14:32 | pool_3: storing incremented val 8 - sleeping\n",
"14:32 | pool_3: setting count to 8\n",
"14:32 | pool_3: *** END DANGER ZONE ***\n",
"14:32 | pool_3: new count is 8\n",
"14:32 | pool_3: releasing lock\n",
"14:32 | pool_4: acquired lock\n",
"14:32 | pool_4: *** START DANGER ZONE ***\n",
"14:32 | pool_4: got local val 8\n",
"14:32 | pool_4: storing decremented val 7 - sleeping\n",
"14:32 | pool_4: setting count to 7\n",
"14:32 | pool_4: *** END DANGER ZONE ***\n",
"14:32 | pool_4: new count is 7\n",
"14:32 | pool_4: releasing lock\n",
"14:32 | pool_0: acquired lock\n",
"14:32 | pool_0: *** START DANGER ZONE ***\n",
"14:32 | pool_0: got local val 7\n",
"14:32 | pool_0: storing incremented val 8 - sleeping\n",
"14:32 | pool_0: setting count to 8\n",
"14:32 | pool_0: *** END DANGER ZONE ***\n",
"14:32 | pool_0: new count is 8\n",
"14:32 | pool_0: releasing lock\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 8\n",
"14:32 | pool_1: storing decremented val 7 - sleeping\n",
"14:32 | pool_1: setting count to 7\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 7\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 7\n",
"14:32 | pool_1: storing decremented val 6 - sleeping\n",
"14:32 | pool_1: setting count to 6\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 6\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 6\n",
"14:32 | pool_1: storing decremented val 5 - sleeping\n",
"14:32 | pool_1: setting count to 5\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 5\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 5\n",
"14:32 | pool_1: storing decremented val 4 - sleeping\n",
"14:32 | pool_1: setting count to 4\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 4\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 4\n",
"14:32 | pool_1: storing decremented val 3 - sleeping\n",
"14:32 | pool_1: setting count to 3\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 3\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 3\n",
"14:32 | pool_1: storing decremented val 2 - sleeping\n",
"14:32 | pool_1: setting count to 2\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 2\n",
"14:32 | pool_1: releasing lock\n",
"14:32 | pool_1: attempting to start decrement operation\n",
"14:32 | pool_1: acquired lock\n",
"14:32 | pool_1: *** START DANGER ZONE ***\n",
"14:32 | pool_1: got local val 2\n",
"14:32 | pool_1: storing decremented val 1 - sleeping\n",
"14:32 | pool_1: setting count to 1\n",
"14:32 | pool_1: *** END DANGER ZONE ***\n",
"14:32 | pool_1: new count is 1\n",
"14:32 | pool_1: releasing lock\n"
]
},
{
"name": "stdout",
"output_type": "stream",
"text": [
"Pool locked multi thread ended at 1\n"
]
}
],
"source": [
"# Detailed view of run with debugging:\n",
"logging.getLogger().setLevel(logging.DEBUG)\n",
"pool_locked_multi_thread()"
]
}
],
"metadata": {
"kernelspec": {
"display_name": "py37",
"language": "python",
"name": "py37"
},
"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.7.4"
}
},
"nbformat": 4,
"nbformat_minor": 4
}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment