Advanced asyncio: Solving Real-world Production Problems (original) (raw)

")

")

[C...")
on darwin Type "help", "copyright", "credits" or "license" for more information. >>> import asyncio, datetime >>> async def hello(): ... print(f'[{datetime.datetime.now()}] Hello...') ... await asyncio.sleep(1) # some I/O-intensive work ... print(f'[{datetime.datetime.now()}] ...World!') ... >>> asyncio.run(hello()) [2018-07-07 10:45:55.559856] Hello... [2018-07-07 10:45:56.568737] ...World!

[C...")
on darwin Type "help", "copyright", "credits" or "license" for more information. >>> import asyncio, datetime >>> async def hello(): ... print(f'[{datetime.datetime.now()}] Hello...') ... await asyncio.sleep(1) # some I/O-intensive work ... print(f'[{datetime.datetime.now()}] ...World!') ... >>> asyncio.run(hello()) [2018-07-07 10:45:55.559856] Hello... [2018-07-07 10:45:56.568737] ...World! FAKE NEWS

[C...")
on darwin Type "help", "copyright", "credits" or "license" for more information. >>> import asyncio, datetime >>> async def hello(): ... print(f'[{datetime.datetime.now()}] Hello...') ... await asyncio.sleep(1) # some I/O-intensive work ... print(f'[{datetime.datetime.now()}] ...World!') ... >>> asyncio.run(hello()) [2018-07-07 10:45:55.559856] Hello... [2018-07-07 10:45:56.568737] ...World! FAKE NEWS

[C...")
on darwin Type "help", "copyright", "credits" or "license" for more information. >>> import asyncio, datetime >>> async def hello(): ... print(f'[{datetime.datetime.now()}] Hello...') ... await asyncio.sleep(1) # some I/O-intensive work ... print(f'[{datetime.datetime.now()}] ...World!') ... >>> asyncio.run(hello()) [2018-07-07 10:45:55.559856] Hello... [2018-07-07 10:45:56.568737] ...World! FAKE NEWS

")

")

concurrently publish messages
")

concurrently consume messages
")

concurrent work
")

finalization tasks
")

Pulled Message(inst_name='cattle-998c') 13:15:31,486 INFO: Saved Message(inst_name='cattle-zpsk') into database 13:15:31,486 INFO: Done. Acked Message(inst_name='cattle-zpsk') 13:15:31,811 INFO: Pulled Message(inst_name='cattle-j9bu') 13:15:31,863 INFO: Saved Message(inst_name='cattle-998c') into database 13:15:31,903 INFO: Pulled Message(inst_name='cattle-vk5l') 13:15:32,149 INFO: Pulled Message(inst_name='cattle-1lf2') 13:15:32,239 INFO: Restarted cattle-vk5l.example.net 13:15:32,245 INFO: Restarted cattle-998c.example.net 13:15:32,245 INFO: Done. Acked Message(inst_name='cattle-998c') 13:15:32,267 INFO: Saved Message(inst_name='cattle-j9bu') into database 13:15:32,478 INFO: Pulled Message(inst_name='cattle-mflk') 13:15:32,481 INFO: Restarted cattle-j9bu.example.net 13:15:32,482 INFO: Done. Acked Message(inst_name='cattle-j9bu') 13:15:32,505 INFO: Pulled Message(inst_name='cattle-t7tv') unblocking: finalization tasks

13:15:31,250 INF...")
cattle-zpsk.example.net 13:15:31,347 INFO: Pulled Message(inst_name='cattle-998c') 13:15:31,486 INFO: Saved Message(inst_name='cattle-zpsk') into database 13:15:31,486 INFO: Done. Acked Message(inst_name='cattle-zpsk') 13:15:31,811 INFO: Pulled Message(inst_name='cattle-j9bu') 13:15:31,863 INFO: Saved Message(inst_name='cattle-998c') into database 13:15:31,903 INFO: Pulled Message(inst_name='cattle-vk5l') 13:15:32,149 INFO: Pulled Message(inst_name='cattle-1lf2') 13:15:32,239 INFO: Restarted cattle-vk5l.example.net 13:15:32,245 INFO: Restarted cattle-998c.example.net 13:15:32,245 INFO: Done. Acked Message(inst_name='cattle-998c') 13:15:32,267 INFO: Saved Message(inst_name='cattle-j9bu') into database 13:15:32,478 INFO: Pulled Message(inst_name='cattle-mflk') 13:15:32,481 INFO: Restarted cattle-j9bu.example.net 13:15:32,482 INFO: Done. Acked Message(inst_name='cattle-j9bu') 13:15:32,505 INFO: Pulled Message(inst_name='cattle-t7tv')

13:15:31,250 INF...")
cattle-zpsk.example.net 13:15:31,347 INFO: Pulled Message(inst_name='cattle-998c') 13:15:31,486 INFO: Saved Message(inst_name='cattle-zpsk') into database 13:15:31,486 INFO: Done. Acked Message(inst_name='cattle-zpsk') 13:15:31,811 INFO: Pulled Message(inst_name='cattle-j9bu') 13:15:31,863 INFO: Saved Message(inst_name='cattle-998c') into database 13:15:31,903 INFO: Pulled Message(inst_name='cattle-vk5l') 13:15:32,149 INFO: Pulled Message(inst_name='cattle-1lf2') 13:15:32,239 INFO: Restarted cattle-vk5l.example.net 13:15:32,245 INFO: Restarted cattle-998c.example.net 13:15:32,245 INFO: Done. Acked Message(inst_name='cattle-998c') 13:15:32,267 INFO: Saved Message(inst_name='cattle-j9bu') into database 13:15:32,478 INFO: Pulled Message(inst_name='cattle-mflk') 13:15:32,481 INFO: Restarted cattle-j9bu.example.net 13:15:32,482 INFO: Done. Acked Message(inst_name='cattle-j9bu') 13:15:32,505 INFO: Pulled Message(inst_name='cattle-t7tv')

")

responding to signals
")

$ pkill -INT -f "python mayh...")
INFO: Pulled Message(inst_name='cattle-lrnm') 19:11:25,321 INFO: Done. Acked Message(inst_name='cattle-lrnm') 19:11:25,700 INFO: Pulled Message(inst_name='cattle-m0f6') 19:11:25,700 INFO: Done. Acked Message(inst_name='cattle-m0f6') 19:11:25,740 INFO: Saved Message(inst_name='cattle-m0f6') into database 19:11:25,840 INFO: Saved Message(inst_name='cattle-lrnm') into database 19:11:26,144 INFO: Process interrupted 19:11:26,144 INFO: Cleaning up responding to signals

$ python mayhem.py
$ pkil...")
"python mayhem.py" 19:11:25,321 INFO: Pulled Message(inst_name='cattle-lrnm') 19:11:25,321 INFO: Done. Acked Message(inst_name='cattle-lrnm') 19:11:25,700 INFO: Pulled Message(inst_name='cattle-m0f6') 19:11:25,700 INFO: Done. Acked Message(inst_name='cattle-m0f6') 19:11:25,740 INFO: Saved Message(inst_name='cattle-m0f6') into database 19:11:25,840 INFO: Saved Message(inst_name='cattle-lrnm') into database 19:11:26,144 INFO: Process interrupted 19:11:26,144 INFO: Cleaning up

$ pkill -TERM -f "python may...")
INFO: Pulled Message(inst_name='cattle-npww') 19:08:25,554 INFO: Done. Acked Message(inst_name='cattle-npww') 19:08:25,655 INFO: Pulled Message(inst_name='cattle-rm7n') 19:08:25,655 INFO: Done. Acked Message(inst_name='cattle-rm7n') 19:08:25,790 INFO: Saved Message(inst_name='cattle-rm7n') into database 19:08:25,831 INFO: Saved Message(inst_name='cattle-npww') into database [1] 78851 terminated python mandrill/mayhem.py responding to signals

$ python mayhem.py
$ pkil...")
"python mayhem.py" 19:08:25,553 INFO: Pulled Message(inst_name='cattle-npww') 19:08:25,554 INFO: Done. Acked Message(inst_name='cattle-npww') 19:08:25,655 INFO: Pulled Message(inst_name='cattle-rm7n') 19:08:25,655 INFO: Done. Acked Message(inst_name='cattle-rm7n') 19:08:25,790 INFO: Saved Message(inst_name='cattle-rm7n') into database 19:08:25,831 INFO: Saved Message(inst_name='cattle-npww') into database [1] 78851 terminated python mandrill/mayhem.py

def main():
queue = async...")
asyncio.get_event_loop() # <-- could happen here or earlier try: loop.create_task(publish(queue)) loop.create_task(consume(queue)) loop.run_forever() except KeyboardInterrupt: logging.info("Process interrupted") # <-- could happen here finally: logging.info("Cleaning up") # <-- could happen here loop.close() # <-- could happen here

signal handler
")

or -HUP or -INT

$ pkill -T...")
-TERM -f "python mayhem.py" 19:11:25,321 INFO: Pulled Message(inst_name='cattle-lrnm') 19:11:25,321 INFO: Done. Acked Message(inst_name='cattle-lrnm') 19:11:25,700 INFO: Pulled Message(inst_name='cattle-m0f6') 19:11:25,700 INFO: Done. Acked Message(inst_name='cattle-m0f6') 19:11:25,740 INFO: Saved Message(inst_name='cattle-m0f6') into database 19:11:25,840 INFO: Saved Message(inst_name='cattle-lrnm') into database 19:11:26,143 INFO: Received exit signal SIGTERM... 19:11:26,143 INFO: Closing database connections 19:11:26,144 INFO: Cancelling 19 outstanding tasks 19:11:26,144 INFO: Flushing metrics 19:11:26,145 INFO: Cleaning up signal handler

$ python mayhem.py

or -HUP or ...")

$ pkill -TERM -f "python mayhem.py" 19:11:25,321 INFO: Pulled Message(inst_name='cattle-lrnm') 19:11:25,321 INFO: Done. Acked Message(inst_name='cattle-lrnm') 19:11:25,700 INFO: Pulled Message(inst_name='cattle-m0f6') 19:11:25,700 INFO: Done. Acked Message(inst_name='cattle-m0f6') 19:11:25,740 INFO: Saved Message(inst_name='cattle-m0f6') into database 19:11:25,840 INFO: Saved Message(inst_name='cattle-lrnm') into database 19:11:26,143 INFO: Received exit signal SIGTERM... 19:11:26,143 INFO: Closing database connections 19:11:26,144 INFO: Cancelling 19 outstanding tasks 19:11:26,144 INFO: Flushing metrics 19:11:26,145 INFO: Cleaning up

which signals to care about
")

not-so-graceful asyncio.shie...")

...
def main():
loop ...")
= (signal.SIGHUP, signal.SIGTERM, signal.SIGINT) for s in signals: loop.add_signal_handler( s, lambda s=s: asyncio.create_task(shutdown(s, loop))) shielded_coro = asyncio.shield(cant_stop_me()) try: loop.run_until_complete(shielded_coro) finally: logging.info("Cleaning up") loop.close() ungraceful shutdown: asyncio.shield

^C13:24:21,156 IN...")
13:24:21,156 INFO: Cancelling 2 outstanding tasks 13:24:21,156 INFO: Coroutine cancelled 13:24:21,157 INFO: Cleaning up Traceback (most recent call last): File "examples/shield_test.py", line 62, in loop.run_until_complete(shielded_coro) File "/Users/lynn/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.p return future.result() concurrent.futures._base.CancelledError ungraceful shutdown: asyncio.shield

^C18:27:18,982 IN...")
recent call last): File "shield_test_no_shutdown.py", line 23, in loop.run_until_complete(shielded_coro) File "/Users/lynn/.pyenv/versions/3.6.2/lib/python3.6/asyncio/base_events.p self.run_forever() File "/Users/lynn/.pyenv/versions/3.6.2/lib/python3.6/asyncio/base_events.p self._run_once() File "/Users/lynn/.pyenv/versions/3.6.2/lib/python3.6/asyncio/base_events.p event_list = self._selector.select(timeout) File "/Users/lynn/.pyenv/versions/3.6.2/lib/python3.6/selectors.py", line 5 kev_list = self._kqueue.control(None, max_ev, timeout) KeyboardInterrupt ungraceful shutdown: asyncio.shield

18:43:55,730 INFO...")
python3.7/asyncio/tasks.py:660]> Traceback (most recent call last): File "shield_test_no_shutdown.py", line 38, in asyncio.run(main()) File "/Users/lynn/.pyenv/versions/3.7.0/lib/python3.7/asyncio/runners.py", return loop.run_until_complete(main) File "/Users/lynn/.pyenv/versions/3.7.0/lib/python3.7/asyncio/base_events.p return future.result() concurrent.futures._base.CancelledError ungraceful shutdown: asyncio.shield

")

global handler
")

global handler
")

13:49:33,524 INFO: Pulled Me...")
Message(inst_name='cattle-5i2f') 13:49:33,925 ERROR: Task exception was never retrieved future: <Task finished coro=<restart_host() done, defined at mayhem_ex_handling.py:56> exception=Exception('Could not restart cattle-5i2f.example.net')> Traceback (most recent call last): File "mayhem_ex_handling.py", line 60, in restart_host raise Exception(f"Could not restart {msg.hostname}") Exception: Could not restart cattle-5i2f.example.net 13:49:34,247 INFO: Pulled Message(inst_name='cattle-e086') 13:49:34,432 INFO: Saved Message(inst_name='cattle-hvy0') into database 13:49:34,517 INFO: Restarted cattle-hvy0.example.net global handler

$ python mayhem.py
13:49:33,524 ...")
INFO: Pulled Message(inst_name='cattle-5i2f') 13:49:33,925 ERROR: Task exception was never retrieved future: <Task finished coro=<restart_host() done, defined at mayhem_ex_handling.py:56> exception=Exception('Could not restart cattle-5i2f.example.net')> Traceback (most recent call last): File "mayhem_ex_handling.py", line 60, in restart_host raise Exception(f"Could not restart {msg.hostname}") Exception: Could not restart cattle-5i2f.example.net 13:49:34,247 INFO: Pulled Message(inst_name='cattle-e086') 13:49:34,432 INFO: Saved Message(inst_name='cattle-hvy0') into database 13:49:34,517 INFO: Restarted cattle-hvy0.example.net

$ python mayhem.py
13:49:33,524 ...")
INFO: Pulled Message(inst_name='cattle-5i2f') 13:49:33,925 ERROR: Task exception was never retrieved future: <Task finished coro=<restart_host() done, defined at mayhem_ex_handling.py:56> exception=Exception('Could not restart cattle-5i2f.example.net')> Traceback (most recent call last): File "mayhem_ex_handling.py", line 60, in restart_host raise Exception(f"Could not restart {msg.hostname}") Exception: Could not restart cattle-5i2f.example.net 13:49:34,247 INFO: Pulled Message(inst_name='cattle-e086') 13:49:34,432 INFO: Saved Message(inst_name='cattle-hvy0') into database 13:49:34,517 INFO: Restarted cattle-hvy0.example.net

logging.e...")

global handler
")

14:01:56,187 INFO: Pulled Me...")
cattle-i490.example.net 14:01:56,241 INFO: Pulled Message(instance_name='cattle-31is') 14:01:56,331 INFO: Saved Message(instance_name='cattle-31is') into database 14:01:56,535 INFO: Pulled Message(instance_name='cattle-sx7f') 14:01:56,535 ERROR: Caught exception: Could not restart cattle-sx7f.example.n 14:01:56,730 INFO: Pulled Message(instance_name='cattle-hsh9') 14:01:56,731 INFO: Saved Message(instance_name='cattle-sx7f') into database 14:01:56,759 INFO: Pulled Message(instance_name='cattle-g20p') 14:01:56,800 INFO: Restarted cattle-31is.example.net 14:01:57,26 INFO: Saved Message(instance_name='cattle-i490') into database 14:01:57,45 INFO: Saved Message(instance_name='cattle-hsh9') into database 14:01:57,181 INFO: Saved Message(instance_name='cattle-g20p') into database 14:01:57,194 INFO: Restarted cattle-g20p.example.net global handler

$ python mayhem.py
14:01:56,187 ...")
INFO: Restarted cattle-i490.example.net 14:01:56,241 INFO: Pulled Message(instance_name='cattle-31is') 14:01:56,331 INFO: Saved Message(instance_name='cattle-31is') into database 14:01:56,535 INFO: Pulled Message(instance_name='cattle-sx7f') 14:01:56,535 ERROR: Caught exception: Could not restart cattle-sx7f 14:01:56,730 INFO: Pulled Message(instance_name='cattle-hsh9') 14:01:56,731 INFO: Saved Message(instance_name='cattle-sx7f') into database 14:01:56,759 INFO: Pulled Message(instance_name='cattle-g20p') 14:01:56,800 INFO: Restarted cattle-31is.example.net 14:01:57,26 INFO: Saved Message(instance_name='cattle-i490') into database 14:01:57,45 INFO: Saved Message(instance_name='cattle-hsh9') into database 14:01:57,181 INFO: Saved Message(instance_name='cattle-g20p') into database 14:01:57,194 INFO: Restarted cattle-g20p.example.net

specific handlers
")

await asyncio.ga...")

")

running coroutines from oth...")

threaded_pubsub_client....")

16:45:36,...")
ERROR: Top-level exception occurred in callback while processing a message Traceback (most recent call last): File "/Users/lynn/.pyenv/versions/ep18-37/lib/python3.7/site-packages/ google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 63, in _wrap_callback_errors callback(message) File "mayhem.py", line 115, in callback asyncio.create_task(handle_message(data)) File "/Users/lynn/.pyenv/versions/3.7.0/lib/python3.7/asyncio/tasks.py", line 320, in create_task loop = events.get_running_loop() RuntimeError: no running event loop

16:45:36,...")
ERROR: Top-level exception occurred in callback while processing a message Traceback (most recent call last): File "/Users/lynn/.pyenv/versions/ep18-37/lib/python3.7/site-packages/ google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 63, in _wrap_callback_errors callback(message) File "mayhem.py", line 115, in callback asyncio.create_task(handle_message(data)) File "/Users/lynn/.pyenv/versions/3.7.0/lib/python3.7/asyncio/tasks.py", line 320, in create_task loop = events.get_running_loop() RuntimeError: no running event loop

Running something else 18:08:10,721 INFO: Saved Message(inst_name='e8x5') into database 18:08:10,828 INFO: Saved Message(inst_name='xbci') into database 18:08:10,828 ERROR: Caught exception: Could not restart xbci.example.net 18:08:11,549 INFO: Restarted e8x5.example.net 18:08:11,821 INFO: Done. Message(inst_name='e8x5') 18:08:12,108 INFO: Running something else 18:08:12,276 INFO: Done. Message(inst_name='xbci') running coroutines from other threads

running coroutines from oth...")

")

simple testing with pytest
")

mocking coroutines
")

testing create_task
")

async def test_consume(moc...")
create_coro_mock("mandrill.handle_message") mock_get.side_effect = [message, Exception("break while loop")] with pytest.raises(Exception, match="break while loop"): await mayhem.consume(mock_queue) ret_tasks = [ t for t in asyncio.all_tasks() if t is not asyncio.current_task() ] assert 1 == len(ret_tasks) mock_handle_message.assert_not_called() # <-- sanity check await asyncio.gather(*ret_tasks) mock_handle_message.assert_called_once_with(message) testing create_task

testing the event loop
")

def test_main(create_moc...")
mayhem.main() assert signal.SIGTERM in event_loop._signal_handlers assert mayhem.handle_exception == event_loop.get_exception_handler() mock_consume.assert_called_once_with(mock_queue) mock_publish.assert_called_once_with(mock_queue) mock_shutdown_gather.assert_called_once_with() # asserting the loop is stopped but not closed assert not event_loop.is_running() assert not event_loop.is_closed() event_loop.close.assert_called_once_with()

def test_main(create_moc...")
mayhem.main() assert signal.SIGTERM in event_loop._signal_handlers assert mayhem.handle_exception == event_loop.get_exception_handler() mock_consume.assert_called_once_with(mock_queue) mock_publish.assert_called_once_with(mock_queue) mock_shutdown_gather.assert_called_once_with() # asserting the loop is stopped but not closed assert not event_loop.is_running() assert not event_loop.is_closed() event_loop.close.assert_called_once_with()

_ = create_mock_coro("mayhem.consume") mock_publish, _ = create_mock_coro("mayhem.publish") mock_shutdown_gather, _ = create_mock_coro("mayhem.asyncio.gather") def _send_signal(): time.sleep(0.1) os.kill(os.getpid(), sig_to_test) thread = threading.Thread(target=_send_signal, daemon=True) thread.start() mandrill.main() assert sig_to_test in event_loop._signal_handlers # <--snip--> testing the event loop

@pytest.mark.parametrize...")
create_mock_coro, event_loop, mock_queue): mock_consume, _ = create_mock_coro("mayhem.consume") mock_publish, _ = create_mock_coro("mayhem.publish") mock_shutdown_gather, _ = create_mock_coro("mayhem.asyncio.gather") def _send_signal(): time.sleep(0.1) os.kill(os.getpid(), sig_to_test) thread = threading.Thread(target=_send_signal, daemon=True) thread.start() mandrill.main() assert sig_to_test in event_loop._signal_handlers # <--snip-->

")

manual debugging
")

"mayhem.py", line 107, in handle_message save_coro, restart_coro, return_exceptions=True Stack for <Task pending coro=<handle_message() running at mayhem.py:107> wait File "mayhem.py", line 107, in handle_message save_coro, restart_coro, return_exceptions=True Stack for <Task pending coro=<cleanup() running at mayhem.py:78> wait_for=<Fu File "mayhem.py", line 78, in cleanup await asyncio.sleep(random.random()) Stack for <Task pending coro=<consume() running at mayhem.py:115> wait_for=<F File "mayhem.py", line 115, in consume msg = await queue.get() Stack for <Task pending coro=<restart_host() running at mayhem.py:62> wait_fo File "mayhem.py", line 62, in restart_host await asyncio.sleep(random.randrange(1, 3)) manual debugging

"mayhem.py", line 107, in handle_message save_coro, restart_coro, return_exceptions=True Stack for <Task pending coro=<handle_message() running at mayhem.py:107> wait File "mayhem.py", line 107, in handle_message save_coro, restart_coro, return_exceptions=True Stack for <Task pending coro=<cleanup() running at mayhem.py:78> wait_for=<Fu File "mayhem.py", line 78, in cleanup await asyncio.sleep(random.random()) Stack for <Task pending coro=<consume() running at mayhem.py:115> wait_for=<F File "mayhem.py", line 115, in consume msg = await queue.get() Stack for <Task pending coro=<restart_host() running at mayhem.py:62> wait_fo File "mayhem.py", line 62, in restart_host await asyncio.sleep(random.randrange(1, 3)) manual debugging

using debug mode
")

using d...")

...> source_traceback: Object created at (most recent call last): File "mayhem.py", line 164, in main() File "mayhem.py", line 157, in main loop.run_forever() File "/Users/lynn/.pyenv/versions/3.7.2/lib/python3.7/asyncio/base_events.p self._run_once() File "/Users/lynn/.pyenv/versions/3.7.2/lib/python3.7/asyncio/base_events.p handle._run() File "/Users/lynn/.pyenv/versions/3.7.2/lib/python3.7/asyncio/events.py", l self._context.run(self._callback, *self._args) File "mayhem.py", line 117, in consume asyncio.create_task(handle_message(msg)) File "/Users/lynn/.pyenv/versions/3.7.2/lib/python3.7/asyncio/tasks.py", li return loop.create_task(coro) using debug mode: traceback context

...> source_traceback: Object created at ... Traceback (most recent call last): File "mayhem.py", line 107, in handle_message save_coro, restart_coro File "mayhem.py", line 60, in restart_host raise Exception(f"Could not restart {msg.hostname}") Exception: Could not restart cattle-ykdc.example.net using debug mode: traceback context

using d...")



20:2...")
in callback while processing a message Traceback (most recent call last): File "/Users/lynn/.pyenv/versions/pycon19/lib/python3.7/site-packages/ google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 63, in _wrap_callback_errors callback(message) File "mayhem.py", line 174, in callback loop.create_task(handle_message(pubsub_msg)) # <-- snip --> RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one using debug mode: thread safety

$ PYTHONASYNCIO...")
20:21:59,954 ERROR: Top-level exception occurred in callback while processing a message Traceback (most recent call last): File "/Users/lynn/.pyenv/versions/pycon19/lib/python3.7/site-packages/ google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 63, in _wrap_callback_errors callback(message) File "mayhem.py", line 174, in callback loop.create_task(handle_message(pubsub_msg)) # <-- snip --> RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one

using d...")

$ PYTHONASYNCIODEB...")
20:00:57,781 INFO: Pulled Message(inst_name='cattle-okxa') 20:00:57,782 INFO: Extended deadline 3s for Message(inst_name='cattle-okxa') 20:00:59,416 INFO: Saved Message(inst_name='cattle-okxa') into database 20:00:59,417 WARNING: Executing <Task finished coro=<save() done, defined at mayhem.py:68> result=None created at /Users/lynn/.pyenv/versions/3.7.2/lib/python3.7/asyncio/ tasks.py:719> took 1.634 seconds 20:00:59,418 INFO: Pulled Message(instance_name='cattle-pmbv')

debugging in production
")

")

cProfile
")

mayhem.py ncalls tottime percall ... filename:lineno(function) 134 4.785 0.036 ... {method 'control' of 'select.kqueue' objects} 17 0.007 0.000 ... {built-in method _imp.create_dynamic} 62 0.007 0.000 ... {built-in method marshal.loads} 132 0.003 0.000 ... base_events.py:1679(_run_once) 217/216 0.003 0.000 ... {built-in method builtins.__build_class__} 361 0.003 0.000 ... {built-in method posix.stat} 62 0.002 0.000 ... <frozen importlib._bootstrap_external>:914(ge 42 0.002 0.000 ... {built-in method builtins.compile} 195 0.001 0.000 ... <frozen importlib._bootstrap_external>:1356(f 50 0.001 0.000 ... {method 'write' of '_io.TextIOWrapper' object 122 0.001 0.000 ... _make.py:1217(__repr__) 50 0.001 0.000 ... __init__.py:293(__init__) 18 0.001 0.000 ... enum.py:134(__new__) 72/15 0.001 0.000 ... sre_parse.py:475(_parse) 62 0.001 0.000 ... {method 'read' of '_io.FileIO' objects} cProfile

mayhem.py ncalls tottime percall ... filename:lineno(function) 134 4.785 0.036 ... {method 'control' of 'select.kqueue' objects} 17 0.007 0.000 ... {built-in method _imp.create_dynamic} 62 0.007 0.000 ... {built-in method marshal.loads} 132 0.003 0.000 ... base_events.py:1679(_run_once) 217/216 0.003 0.000 ... {built-in method builtins.__build_class__} 361 0.003 0.000 ... {built-in method posix.stat} 62 0.002 0.000 ... <frozen importlib._bootstrap_external>:914(ge 42 0.002 0.000 ... {built-in method builtins.compile} 195 0.001 0.000 ... <frozen importlib._bootstrap_external>:1356(f 50 0.001 0.000 ... {method 'write' of '_io.TextIOWrapper' object 122 0.001 0.000 ... _make.py:1217(__repr__) 50 0.001 0.000 ... __init__.py:293(__init__) 18 0.001 0.000 ... enum.py:134(__new__) 72/15 0.001 0.000 ... sre_parse.py:475(_parse) 62 0.001 0.000 ... {method 'read' of '_io.FileIO' objects} cProfile

mayhem.py ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 4.704 4.704 mayhem.py:141(main) 18 0.000 0.000 0.002 0.000 mayhem.py:56(restart_host) 22 0.000 0.000 0.003 0.000 mayhem.py:67(save) 33 0.000 0.000 0.003 0.000 mayhem.py:74(cleanup) 22 0.000 0.000 0.002 0.000 mayhem.py:83(extend) 11 0.000 0.000 0.000 0.000 mayhem.py:91(handle_results) 12 0.000 0.000 0.002 0.000 mayhem.py:41(publish) 22 0.000 0.000 0.002 0.000 mayhem.py:97(handle_message) 12 0.000 0.000 0.003 0.000 mayhem.py:114(consume) 11 0.000 0.000 0.000 0.000 mayhem.py:37(__attrs_post_init_ 1 0.000 0.000 0.000 0.000 mayhem.py:26(Message) 1 0.000 0.000 0.000 0.000 mayhem.py:130() 2 0.000 0.000 0.001 0.000 mayhem.py:126(shutdown) 1 0.000 0.000 0.000 0.000 mayhem.py:148() cProfile

$ timeout -s INT 5s python -m cProfile...")
filename mayhem.py ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 4.704 4.704 mayhem.py:141(main) 18 0.000 0.000 0.002 0.000 mayhem.py:56(restart_host) 22 0.000 0.000 0.003 0.000 mayhem.py:67(save) 33 0.000 0.000 0.003 0.000 mayhem.py:74(cleanup) 22 0.000 0.000 0.002 0.000 mayhem.py:83(extend) 11 0.000 0.000 0.000 0.000 mayhem.py:91(handle_results) 12 0.000 0.000 0.002 0.000 mayhem.py:41(publish) 22 0.000 0.000 0.002 0.000 mayhem.py:97(handle_message) 12 0.000 0.000 0.003 0.000 mayhem.py:114(consume) 11 0.000 0.000 0.000 0.000 mayhem.py:37(__attrs_post_init_ 1 0.000 0.000 0.000 0.000 mayhem.py:26(Message) 1 0.000 0.000 0.000 0.000 mayhem.py:130() 2 0.000 0.000 0.001 0.000 mayhem.py:126(shutdown) 1 0.000 0.000 0.000 0.000 mayhem.py:148()

cProfile with KCacheGrind
")

line_profiler
")

$ python -m line_profiler mayhem.prof Timer unit: 1e-06 s Total time: 0.002202 s File: mayhem.py Function: save at line 69 Line # Hits Time Per Hit % Time Line Contents ======================================================= 69 @profile 70 async def save(msg): 71 8 259.0 32.4 11.8 await asyncio.sleep(random.rand 72 8 26.0 3.2 1.2 msg.saved = True 73 8 1917.0 239.6 87.1 logging.info(f"Saved {msg} into line_profiler

$ python -m line_profiler mayhem.prof Timer unit: 1e-06 s Total time: 0.002202 s File: mayhem.py Function: save at line 69 Line # Hits Time Per Hit % Time Line Contents ======================================================= 69 @profile 70 async def save(msg): 71 8 259.0 32.4 11.8 await asyncio.sleep(random.rand 72 8 26.0 3.2 1.2 msg.saved = True 73 8 1917.0 239.6 87.1 logging.info(f"Saved {msg} into line_profiler

$ python -m line_profiler mayhem.prof Timer unit: 1e-06 s Total time: 0.002202 s File: mayhem.py Function: save at line 69 Line # Hits Time Per Hit % Time Line Contents ======================================================= 69 @profile 70 async def save(msg): 71 8 259.0 32.4 11.8 await asyncio.sleep(random.rand 72 8 26.0 3.2 1.2 msg.saved = True 73 8 1917.0 239.6 87.1 logging.info(f"Saved {msg} into line_profiler

logger = aiologger.Logger.with...")

$ python -m line_profiler mayhem.prof Timer unit: 1e-06 s Total time: 0.0011 s File: mayhem.py Function: save at line 69 Line # Hits Time Per Hit % Time Line Contents ======================================================= 69 @profile 70 async def save(msg): 71 7 269.0 38.4 24.5 await asyncio.sleep(random.rand 72 5 23.0 4.6 2.1 msg.saved = True 73 5 808.0 161.6 73.5 await logger.info(f"Saved {msg} line_profiler

$ python -m line_profiler mayhem.prof Timer unit: 1e-06 s Total time: 0.0011 s File: mayhem.py Function: save at line 69 Line # Hits Time Per Hit % Time Line Contents ======================================================= 69 @profile 70 async def save(msg): 71 7 269.0 38.4 24.5 await asyncio.sleep(random.rand 72 5 23.0 4.6 2.1 msg.saved = True 73 5 808.0 161.6 73.5 await logger.info(f"Saved {msg} line_profiler

$ python -m line_profiler mayhem.prof Timer unit: 1e-06 s Total time: 0.0011 s File: mayhem.py Function: save at line 69 Line # Hits Time Per Hit % Time Line Contents ======================================================= 69 @profile 70 async def save(msg): 71 7 269.0 38.4 24.5 await asyncio.sleep(random.rand 72 5 23.0 4.6 2.1 msg.saved = True 73 5 808.0 161.6 73.5 await logger.info(f"Saved {msg} line_profiler

live profiling
")

live ...")

rogue.ly/adv-aio
T...")