Sublime Forum

Mis-ordering of "prints" in console output panel

#1

While playing around with multiple threads in the context of a plugin, I’ve come across the following behavior in the console output panel :

  • prints from plugin_loaded, plugin_unloaded come in the expected order
  • prints from a different thread come several seconds after they have been “printed”

Note : this doesn’t happen when “printing to a file” (aka correct order …)

So does anyone know why this happens ? or in other words : under which condition can I trust the order in the console output panel ?

For reproducibility, I’m on MacOS with sublime 4107.
I managed to trace this from sys.stdout to sublime._LogWriter and finally to sublime_api.log_message but got stuck there :frowning:

thanks for your time
Regards

0 Likes
#2

any actual code? even psuedo ones.

0 Likes
#3

Yes, without code we can only guess what the behavior is.

0 Likes
#4

something as simple as :

import threading
import time
from datetime import datetime

__thread = None
def plugin_loaded():
    global __thread
    print(f"{datetime.now()} plugin_loading")
    __thread = threading.Thread(target=__run)
    __thread.start()
    print(f"{datetime.now()} thread started")
    time.sleep(0.01)
    print(f"{datetime.now()} plugin_loaded")

def plugin_unloaded():
    print(f"{datetime.now()} plugin_unloading")
    if __thread:
        __thread.join()
    print(f"{datetime.now()} plugin_unloaded")

def __run():
    print(f"{datetime.now()} in __run")

yields :

reloading plugin User.test_02
2021-07-09 16:46:42.300284 plugin_unloading
2021-07-09 16:46:42.300316 plugin_unloaded
2021-07-09 16:46:42.301231 plugin_loading
2021-07-09 16:46:42.301367 thread started
2021-07-09 16:46:42.301385 plugin_loaded
2021-07-09 16:46:42.301332 in __run

Note : “in __run” is printed out of order

0 Likes
#5

I don’t see a problem here. You have a data race between the main thread logging “plugin loaded” and the other thread printing “run”. Note that time.sleep depending on operating system may only be accurate to the 10s of milliseconds.

0 Likes
#6

Not a race as the following perhaps more clearly and concisely illustrates :

    import threading
    from datetime import datetime

    def plugin_loaded():
        print(f"{datetime.now()} plugin_loading")
        __thread = threading.Thread(target=__run)
        __thread.start()
        __thread.join()
        print(f"{datetime.now()} after_thread_is_finished")

    def __run():
        print(f"{datetime.now()} in_thread")

with

reloading plugin User.test_02
2021-07-10 02:03:19.639742 plugin_loading
2021-07-10 02:03:19.639934 after_thread_is_finished
2021-07-10 02:03:19.639848 in_thread

The thread is finished / joined so we have finished printing the in_thread line when we print the after_thread_is_finished line and yet …
Again this is counter-intuitive as this doesn’t happen when “printing to a file”

If I were a betting man, I’d wager that sublime_api.log_message is synchronous in the “main” thread and queues messages when not, but I’d much prefer confirmation from someone more knowledgeable than I.

0 Likes
#7

Sorry for the necro. This happens because plugin_loaded is run synchronously on the main thread, so the secondary thread’s print is queued up until the main thread is finished reloading the plugin.

0 Likes