[7.14] Slow coroutine step execution: TunnelCommunity.do_remove()

[kozlovsky]

After the slow coroutine stack tracing was enabled in the debug version of the 7.14 release, some slow coroutines were detected.

One traceback that regularly appears is:

  File "src\<relief>\core\start_core.py", line 206, in run_core
  File "src\<relief>\core\start_core.py", line 169, in run_tribler_core_session
  File "Python38\lib\asyncio\base_events.py", line 603, in run_until_complete
  File "Python38\lib\asyncio\windows_events.py", line 316, in run_forever
  File "Python38\lib\asyncio\base_events.py", line 570, in run_forever
  File "Python38\lib\asyncio\base_events.py", line 1859, in _run_once
  File "core\utilities\slow_coro_detection\patch.py", line 37, in patched_handle_run
  File "Python38\lib\asyncio\events.py", line 81, in _run
  File "Python38\lib\site-packages\ipv8\taskmanager.py", line 18, in interval_runner
  File "Python38\lib\site-packages\ipv8\messaging\anonymization\hidden_services.py", line 194, in do_circuits
  File "Python38\lib\site-packages\ipv8\messaging\anonymization\community.py", line 186, in do_circuits

Here:

    def do_circuits(self):
        for circuit_length, num_circuits in self.circuits_needed.items():
            num_to_build = max(0, num_circuits - len(self.find_circuits(state=None, hops=circuit_length)))
            self.logger.info("Want %d data circuits of length %d", num_to_build, circuit_length)
            for _ in range(num_to_build):
                if not self.create_circuit(circuit_length):
                    self.logger.info("circuit creation of %d circuits failed, no need to continue", num_to_build)
                    break
        self.do_remove()  # <-- line 186

Some registered events with slow execution of the coroutine:

• 2.776 seconds: https://sentry.tribler.org/organizations/tribler/issues/2752/events/0a5f694d88b74c5db37c339a3480dc00/
• 1.934 seconds: https://sentry.tribler.org/organizations/tribler/issues/2752/events/dd30dc5a9fea42cf94b43dd5517af640/
• 1.669 seconds: https://sentry.tribler.org/organizations/tribler/issues/2752/events/c44a52c8ea284157bd6398b92c71409f/
• 1.427 seconds: https://sentry.tribler.org/organizations/tribler/issues/2754/events/d17d342b73814a13b18184e6305e82e4/

In these cases, the actual core crash caused by invalid pointer access was probably not related to the slow execution of the coroutine, but the coroutine step with TunnelCommunity.do_remove was the slowest coroutine step before the crash.

It looks like the do_remove method has no particular line that is especially slow (because otherwise, the stack trace would also display this specific line), and the method just needs a general performance optimization.

[qstokkink]

@egbertbouman can we close this now that the tunnels are Rust-based and super fast, or is this still relevant?

[egbertbouman]

The Rust module doesn't solve this, unfortunately. All the tunnel control logic (which do_remove is part of) is still in Python.

[qstokkink]

I cannot reproduce this slow call on the 8.0 series. I believe, @egbertbouman, you could not reproduce this either (if I'm wrong, feel free to reopen this issue). I assume this issue has now been directly or indirectly fixed.