Unaccounted for time with ThreadPoolExecutor

Question

I have an AWS Lambda function:

import boto3
import json
import concurrent.futures
from stats import Timer

client = boto3.client('lambda')

def do_lambda():
    timer = Timer()
    response = client.invoke(
        FunctionName = 'arn:aws:lambda:us-east-1:497857710590:function:wherewasit-search',
        InvocationType = 'RequestResponse',
        Payload = json.dumps({'keys': 1}))
    payload = json.loads(json.load(response['Payload'])['body'])
    print(f"Response after {timer.stop()}ms")

def do_work(n_threads):
    timer = Timer()
    with concurrent.futures.ThreadPoolExecutor() as executor:
        futures = []
        for i in range(n_threads):
            futures.append(executor.submit(do_lambda))
        for future in concurrent.futures.as_completed(futures):
            pass
    print(f"Joined all: {timer.stop()}ms")

def lambda_handler(event, context):
    do_work(9)
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

The output:

Response after 1236ms
Response after 1242ms
Response after 1251ms
Response after 1272ms
Response after 1322ms
Response after 1359ms
Response after 1126ms
Response after 1170ms
Response after 1246ms
Joined all: 2496ms

Given that all the threads are done in at most 1.4 seconds, what is another second spent on before all the threads are joined?

Answer 1

Maybe your problem has nothing to do with AWS or boto3. Try running this:

#!/usr/bin/env python3

import time
import concurrent.futures

class Timer:
    def __init__(self):
        self.start_time = time.time()
    def stop(self):
        return 1000*(time.time() - self.start_time)

def do_lambda():
    timer = Timer()
    time.sleep(1.2)
    print(f"Response after {timer.stop()}ms")

def do_work(n_threads):
    timer = Timer()
    with concurrent.futures.ThreadPoolExecutor(max_workers=8) as executor:
        futures = []
        for i in range(n_threads):
            futures.append(executor.submit(do_lambda))
        for future in concurrent.futures.as_completed(futures):
            pass
    print(f"Joined all: {timer.stop()}ms")

if __name__ == "__main__":
    do_work(9)

It should produce output very similar to the output from your program. The "Joined all" time is approximately double the "Response after" time printed by any of the nine do_lambda() calls because the thread pool can have no more than eight workers. The last do_lambda() call cannot begin until at least one of the others has finished.

My program explicitly specifies max_workers. Your program creates a thread pool with the default maximum number of workers. What is that number? (The default on my Python installation appears to be 12.) If it's less than nine, but more than four, then the behavior of your program is pretty much what you should expect.

---

Alt explanation: (This seems less likely, but I know nothing about boto3, so maybe...)

Maybe there is some pooled resource that boto3 uses, and maybe the default size of that pool is less than nine but more than four.