0

Can anyone please help understand why a future's done() never returns True (even when future is complete) when created from nested thread (i.e. using ThreadPoolExecutor within another ThreadPoolExecutor, which is required in my business usecase), but a future's done() returns True when created one one level ThreadPoolExecutor

Here is the common code that is used for getting metrics of ThreadPoolExecutor (primarily looking at completed_tasks_cnt which is equal to number of futures with done() = True:

import time
from typing import Callable, Tuple
from concurrent.futures.thread import ThreadPoolExecutor
import logging
import asyncio
import pprint
import traceback
from asyncio.futures import Future
log = logging.getLogger(__name__)
logging.basicConfig(format='[%(asctime)s][%(threadName)s][%(process)d][%(name)s][%(levelname)s] %(message)s', level=logging.NOTSET)


def run_fnc_in_background_thread(executor: ThreadPoolExecutor, fnc: Callable, fnc_args: Tuple=(), loop=None) -> Future:
    """Run fnc (performing a IO bound task) in a daemon Thread

    Args:
        executor: ThreadPoolExecutor (see https://pymotw.com/3/asyncio/executors.html)
        fnc: Callable function to run in thread
        fnc_args: (Tuple): List of function args
        loop: Event loop (Get loop from `asyncio.get_event_loop()` or `asyncio.new_event_loop()`)

    Returns:
        Future: A future object of the task. You can cancel/stop the future
        (https://docs.python.org/3/library/asyncio-future.html#asyncio.Future)
    """
    loop = loop or asyncio.get_event_loop()
    f: Future = loop.run_in_executor(executor, fnc, *fnc_args)
    asyncio.ensure_future(f)
    return f


def slow_running_task(taskid):
    log.info(f"[{taskid}]slow_running_task sleeping for 2sec")
    time.sleep(2)
    log.info(f"[{taskid}]slow_running_task COMPLETED")


def check_status(executor, futures):
    while True:
        # https://stackoverflow.com/a/25474898/558397
        pending_tasks_to_be_started = executor._work_queue.qsize()
        active_threads_cnt = len(executor._threads)

        active_tasks_cnt = 0
        completed_tasks_cnt = 0
        cancelled_tasks_cnt = 0
        exception_raised_tasks_cnt = 0
        for f in futures:
            if f.done():
                completed_tasks_cnt += 1
                if f.cancelled():
                    cancelled_tasks_cnt += 1
                if f.exception():
                    exception_raised_tasks_cnt += 1
            else:
                active_tasks_cnt += 1

        thread_pool_metrics = {
            "pending_tasks_to_be_started": pending_tasks_to_be_started,
            "active_threads_cnt": active_threads_cnt,
            "active_tasks_cnt": active_tasks_cnt,
            "completed_tasks_cnt": completed_tasks_cnt,
            "cancelled_tasks_cnt": cancelled_tasks_cnt,
            "exception_raised_tasks_cnt": exception_raised_tasks_cnt
        }
        log.info(f"thread_pool_metrics:\n{pprint.pformat(thread_pool_metrics)}")
        time.sleep(1)


executor = ThreadPoolExecutor(max_workers=3, thread_name_prefix="MyThread")

def big_thread():
    # run_fnc_in_background_thread(executor, slow_running_task)
    futures = []
    loop = asyncio.new_event_loop()
    asyncio.set_event_loop(loop)
    f1 = run_fnc_in_background_thread(executor, check_status, fnc_args=(executor, futures), loop=loop)
    for taskid in range(2):
        futures.append(run_fnc_in_background_thread(executor, slow_running_task, fnc_args=(taskid,), loop=loop))

As you can see, when I use nested ThreadPoolExecutor (because of my requirement), I get the following output (i.e. completed_tasks_cnt is never incremented: 'completed_tasks_cnt': 0,):



def main():
    run_fnc_in_background_thread(executor, big_thread)
#     big_thread()
    loop = asyncio.get_event_loop()
    loop.run_forever()
main()

Logs:
[2019-08-19 13:42:02,187][MainThread][32025][asyncio][DEBUG] Using selector: EpollSelector
[2019-08-19 13:42:02,189][MyThread_0][32025][asyncio][DEBUG] Using selector: EpollSelector
[2019-08-19 13:42:02,189][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 0,
 'active_threads_cnt': 1,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:02,190][MyThread_2][32025][__main__][INFO] [0]slow_running_task sleeping for 2sec
[2019-08-19 13:42:02,190][MyThread_0][32025][__main__][INFO] [1]slow_running_task sleeping for 2sec
[2019-08-19 13:42:03,195][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:04,195][MyThread_2][32025][__main__][INFO] [0]slow_running_task COMPLETED
[2019-08-19 13:42:04,196][MyThread_0][32025][__main__][INFO] [1]slow_running_task COMPLETED
[2019-08-19 13:42:04,199][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:05,203][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:06,209][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:07,214][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:08,220][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:42:09,225][MyThread_1][32025][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}

But when I call the future from just one level depth of ThreadPoolExecutor, it works: (see 'completed_tasks_cnt': 2,):


def main():
#     run_fnc_in_background_thread(executor, big_thread)
    big_thread()
    loop = asyncio.get_event_loop()
    loop.run_forever()
main()

[2019-08-19 13:43:49,709][MainThread][32239][asyncio][DEBUG] Using selector: EpollSelector
[2019-08-19 13:43:49,710][MyThread_0][32239][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 0,
 'active_threads_cnt': 0,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:43:49,711][MyThread_1][32239][__main__][INFO] [0]slow_running_task sleeping for 2sec
[2019-08-19 13:43:49,711][MyThread_2][32239][__main__][INFO] [1]slow_running_task sleeping for 2sec
[2019-08-19 13:43:50,715][MyThread_0][32239][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:43:51,719][MyThread_0][32239][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 2,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 0,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:43:51,719][MyThread_2][32239][__main__][INFO] [1]slow_running_task COMPLETED
[2019-08-19 13:43:51,719][MyThread_1][32239][__main__][INFO] [0]slow_running_task COMPLETED
[2019-08-19 13:43:52,724][MyThread_0][32239][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 0,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 2,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:43:53,730][MyThread_0][32239][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 0,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 2,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
[2019-08-19 13:43:54,735][MyThread_0][32239][__main__][INFO] thread_pool_metrics:
{'active_tasks_cnt': 0,
 'active_threads_cnt': 3,
 'cancelled_tasks_cnt': 0,
 'completed_tasks_cnt': 2,
 'exception_raised_tasks_cnt': 0,
 'pending_tasks_to_be_started': 0}
amulllb
  • 3,036
  • 7
  • 50
  • 87

1 Answers1

1

Your code calls loop.run_in_executor, but doesn't run the event loop. More precisely, main runs one event loop, but big_thread creates a new one, and run_in_executor gets invoked on the latter. This is a problem because updates to the future objects returned by run_in_executor are applied by callbacks run by the event loop scheduler.

The purpose of run_in_executor is to provide a bridge between concurrent.futures and asyncio. Since you're not using asyncio, you don't need the bridge; instead of loop.run_in_executor(executor, fn, *args) you can simply call executor.submit(fn, *args) and get back a native concurrent.futures future which you can poll without an asyncio event loop.

In other words, define run_fnc_in_background_thread like this, and you will see completed futures:

def run_fnc_in_background_thread(executor, fnc, fnc_args, loop=None):
    return executor.submit(fnc, *fnc_args)

With this change you no longer need main() to run the event loop, so you can replace loop.run_forever() with time.sleep(3600) or whatever.

Note that your code is accessing private attributes of the executor, such as _work_queue and _threads. Doing that is an extremely bad idea because such attributes can be deleted, renamed, or change meaning without prior notice.

user4815162342
  • 141,790
  • 18
  • 296
  • 355