Created
September 20, 2018 23:36
-
-
Save medmunds/1b32fb8873ff87dac8d29c9f0a7f4819 to your computer and use it in GitHub Desktop.
Test botocore performance preparing large API requests in AWS Lambda
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| # This is an AWS Lambda function to help isolate apparent botocore performance issues | |
| # when posting API requests with large parameters (e.g., SES.SendRawEmail with an 8MB | |
| # RawMessage). See https://github.com/boto/botocore/issues/1561. | |
| # | |
| # Recommended Lambda config: | |
| # Runtime: Python 3.6 | |
| # Handler: lambda_function.run_test | |
| # Environment variables: SES_FROM = "[email protected]" | |
| # (if not set, SES will complain, but the timings should still be valid) | |
| # Memory: 256 MB | |
| # Timeout: 3 min 0 sec | |
| # | |
| # This script can also be run in any local Python 3 environment with boto3 installed. | |
| # In Lambda, it will use the pre-installed boto3 unless you bundle a newer one. | |
| import logging | |
| import os | |
| import time | |
| import boto3 | |
| import botocore | |
| # CONFIG | |
| SES_FROM = os.getenv("SES_FROM", "[email protected]") | |
| MESSAGE_SIZE_MB = int(os.getenv("MESSAGE_SIZE_MB", "8")) | |
| LOG_LEVEL = os.getenv("LOG_LEVEL", "INFO") | |
| # INIT | |
| logger = logging.getLogger() | |
| logger.setLevel(LOG_LEVEL) | |
| ses = boto3.client("ses") | |
| # Construct a large, raw email message in memory | |
| ONE_MB = 1024 * 1024 | |
| BODY_LINE = "The maximum message size, including attachments, is 10 MB.\n" | |
| LARGE_BODY = BODY_LINE * (MESSAGE_SIZE_MB * ONE_MB // len(BODY_LINE)) | |
| RAW_MESSAGE = """\ | |
| From: {ses_from} | |
| To: [email protected] | |
| Subject: Approximately {message_size_mb} MB message | |
| {large_body} | |
| """.format( | |
| ses_from=SES_FROM, | |
| message_size_mb=MESSAGE_SIZE_MB, | |
| large_body=LARGE_BODY, | |
| ).replace("\n", "\r\n").encode("utf-8") | |
| # LAMBDA ENTRY | |
| def run_test(event, context): | |
| logger.info("boto3==%s botocore==%s", boto3.__version__, botocore.__version__) | |
| logger.info("ses.send_raw_email sending %s byte message", | |
| "{:,d}".format(len(RAW_MESSAGE))) | |
| response = ses.send_raw_email(RawMessage={"Data": RAW_MESSAGE}) | |
| logger.info("ses.send_raw_email response: %r", response) | |
| # INSTRUMENTATION | |
| level = 0 | |
| def instrument(cls: type, method_name: str): | |
| """Patch class method to log timing info""" | |
| patched_flag = "_instrumented_{method}".format(method=method_name) | |
| if not hasattr(cls, patched_flag): | |
| setattr(cls, patched_flag, True) | |
| full_name = "{cls}.{method}".format(cls=cls.__name__, method=method_name) | |
| orig_method = getattr(cls, method_name) | |
| call_count = 0 | |
| is_callable = hasattr(orig_method, "__call__") # else property descriptor | |
| def instrumented(self, *args, **kwargs): | |
| global level | |
| nonlocal call_count | |
| call_count += 1 | |
| this_call_count = call_count | |
| indent = " " * level | |
| logger.info("%s> %s %d", indent, full_name, this_call_count) | |
| level += 1 | |
| start_perf = time.perf_counter() # high resolution wall clock | |
| start_process = time.process_time() # excludes process sleep time | |
| try: | |
| if is_callable: | |
| return orig_method(self, *args, **kwargs) | |
| else: | |
| return orig_method.__get__(self) | |
| finally: | |
| elapsed_perf = time.perf_counter() - start_perf | |
| elapsed_process = time.process_time() - start_process | |
| level -= 1 | |
| logger.info("%s< %s %d: %0.3fs (%0.3fs in process)", | |
| indent, full_name, this_call_count, elapsed_perf, elapsed_process) | |
| if not is_callable: | |
| instrumented = property(instrumented) | |
| setattr(cls, method_name, instrumented) | |
| from botocore.auth import SigV4Auth | |
| from botocore.awsrequest import AWSRequest, AWSPreparedRequest | |
| from botocore.client import BaseClient | |
| from botocore.endpoint import Endpoint | |
| instrument(AWSRequest, 'body') | |
| instrument(AWSPreparedRequest, 'prepare_body') | |
| instrument(BaseClient, '_make_api_call') | |
| instrument(Endpoint, 'create_request') | |
| instrument(Endpoint, '_send_request') | |
| instrument(Endpoint, '_get_response') | |
| instrument(SigV4Auth, 'add_auth') | |
| if __name__ == "__main__": | |
| import logging | |
| logging.basicConfig() | |
| run_test({}, {}) |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| START RequestId: 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 Version: $LATEST | |
| [INFO] 2018-09-20T23:08:36.914Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 boto3==1.7.74 botocore==1.10.74 | |
| [INFO] 2018-09-20T23:08:36.914Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 ses.send_raw_email sending 8,530,847 byte message | |
| [INFO] 2018-09-20T23:08:36.914Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > BaseClient._make_api_call 1 | |
| [INFO] 2018-09-20T23:08:37.830Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > Endpoint._send_request 1 | |
| [INFO] 2018-09-20T23:08:37.100Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > Endpoint.create_request 1 | |
| [INFO] 2018-09-20T23:08:37.100Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > SigV4Auth.add_auth 1 | |
| [INFO] 2018-09-20T23:08:37.100Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > AWSRequest.body 1 | |
| [INFO] 2018-09-20T23:08:42.440Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < AWSRequest.body 1: 5.340s (0.880s in process) | |
| [INFO] 2018-09-20T23:08:42.440Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > AWSRequest.body 2 | |
| [INFO] 2018-09-20T23:08:47.720Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < AWSRequest.body 2: 5.262s (0.872s in process) | |
| [INFO] 2018-09-20T23:08:47.720Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > AWSRequest.body 3 | |
| [INFO] 2018-09-20T23:08:53.000Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < AWSRequest.body 3: 5.263s (0.868s in process) | |
| [INFO] 2018-09-20T23:08:53.000Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > AWSRequest.body 4 | |
| [INFO] 2018-09-20T23:08:58.260Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < AWSRequest.body 4: 5.240s (0.866s in process) | |
| [INFO] 2018-09-20T23:08:58.583Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < SigV4Auth.add_auth 1: 21.482s (3.542s in process) | |
| [INFO] 2018-09-20T23:08:58.608Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > AWSPreparedRequest.prepare_body 1 | |
| [INFO] 2018-09-20T23:09:03.940Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < AWSPreparedRequest.prepare_body 1: 5.315s (0.879s in process) | |
| [INFO] 2018-09-20T23:09:03.940Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < Endpoint.create_request 1: 26.840s (4.425s in process) | |
| [INFO] 2018-09-20T23:09:03.940Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 > Endpoint._get_response 1 | |
| [INFO] 2018-09-20T23:09:03.940Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 Starting new HTTPS connection (1): email.us-east-1.amazonaws.com | |
| [INFO] 2018-09-20T23:09:05.241Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < Endpoint._get_response 1: 1.301s (0.045s in process) | |
| [INFO] 2018-09-20T23:09:05.241Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < Endpoint._send_request 1: 28.141s (4.471s in process) | |
| [INFO] 2018-09-20T23:09:05.241Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 < BaseClient._make_api_call 1: 28.326s (4.504s in process) | |
| [INFO] 2018-09-20T23:09:05.241Z 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 ses.send_raw_email response: {'MessageId': '01000165f93e7566-e583dc3d-3624-45a3-8d8f-91708129986b-000000', 'ResponseMetadata': {'RequestId': '2ae7a3da-bd2a-11e8-9c1a-3b6430d4ae58', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amzn-requestid': '2ae7a3da-bd2a-11e8-9c1a-3b6430d4ae58', 'content-type': 'text/xml', 'content-length': '338', 'date': 'Thu, 20 Sep 2018 23:09:04 GMT'}, 'RetryAttempts': 0}} | |
| END RequestId: 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 | |
| REPORT RequestId: 1a4cb23e-bd2a-11e8-a4da-5db63a5885d6 Duration: 28327.92 ms Billed Duration: 28400 ms Memory Size: 256 MB Max Memory Used: 184 MB |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| START RequestId: 05ecabb7-bd2b-11e8-8256-41a843575de5 Version: $LATEST | |
| [INFO] 2018-09-20T23:15:12.170Z 05ecabb7-bd2b-11e8-8256-41a843575de5 boto3==1.9.8 botocore==1.12.8 | |
| [INFO] 2018-09-20T23:15:12.170Z 05ecabb7-bd2b-11e8-8256-41a843575de5 ses.send_raw_email sending 8,530,847 byte message | |
| [INFO] 2018-09-20T23:15:12.170Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > BaseClient._make_api_call 1 | |
| [INFO] 2018-09-20T23:15:12.360Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > Endpoint._send_request 1 | |
| [INFO] 2018-09-20T23:15:12.360Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > Endpoint.create_request 1 | |
| [INFO] 2018-09-20T23:15:12.360Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > SigV4Auth.add_auth 1 | |
| [INFO] 2018-09-20T23:15:12.361Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSRequest.body 1 | |
| [INFO] 2018-09-20T23:15:12.361Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 1 | |
| [INFO] 2018-09-20T23:15:17.720Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 1: 5.342s (0.882s in process) | |
| [INFO] 2018-09-20T23:15:17.720Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 2 | |
| [INFO] 2018-09-20T23:15:23.600Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 2: 5.323s (0.883s in process) | |
| [INFO] 2018-09-20T23:15:23.800Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSRequest.body 1: 10.702s (1.769s in process) | |
| [INFO] 2018-09-20T23:15:23.800Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSRequest.body 2 | |
| [INFO] 2018-09-20T23:15:23.800Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 3 | |
| [INFO] 2018-09-20T23:15:28.381Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 3: 5.300s (0.872s in process) | |
| [INFO] 2018-09-20T23:15:28.400Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 4 | |
| [INFO] 2018-09-20T23:15:33.760Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 4: 5.341s (0.885s in process) | |
| [INFO] 2018-09-20T23:15:33.780Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSRequest.body 2: 10.683s (1.760s in process) | |
| [INFO] 2018-09-20T23:15:33.780Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSRequest.body 3 | |
| [INFO] 2018-09-20T23:15:33.780Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 5 | |
| [INFO] 2018-09-20T23:15:39.800Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 5: 5.281s (0.873s in process) | |
| [INFO] 2018-09-20T23:15:39.800Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 6 | |
| [INFO] 2018-09-20T23:15:44.461Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 6: 5.381s (0.887s in process) | |
| [INFO] 2018-09-20T23:15:44.480Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSRequest.body 3: 10.700s (1.763s in process) | |
| [INFO] 2018-09-20T23:15:44.480Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSRequest.body 4 | |
| [INFO] 2018-09-20T23:15:44.480Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 7 | |
| [INFO] 2018-09-20T23:15:49.780Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 7: 5.300s (0.876s in process) | |
| [INFO] 2018-09-20T23:15:49.800Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 8 | |
| [INFO] 2018-09-20T23:15:55.181Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 8: 5.381s (0.889s in process) | |
| [INFO] 2018-09-20T23:15:55.200Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSRequest.body 4: 10.704s (1.768s in process) | |
| [INFO] 2018-09-20T23:15:55.522Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < SigV4Auth.add_auth 1: 43.162s (7.116s in process) | |
| [INFO] 2018-09-20T23:15:55.523Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > AWSPreparedRequest.prepare_body 9 | |
| [INFO] 2018-09-20T23:16:00.820Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < AWSPreparedRequest.prepare_body 9: 5.280s (0.871s in process) | |
| [INFO] 2018-09-20T23:16:00.820Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < Endpoint.create_request 1: 48.460s (7.988s in process) | |
| [INFO] 2018-09-20T23:16:00.820Z 05ecabb7-bd2b-11e8-8256-41a843575de5 > Endpoint._get_response 1 | |
| [INFO] 2018-09-20T23:16:02.870Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < Endpoint._get_response 1: 1.267s (0.052s in process) | |
| [INFO] 2018-09-20T23:16:02.890Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < Endpoint._send_request 1: 49.729s (8.042s in process) | |
| [INFO] 2018-09-20T23:16:02.100Z 05ecabb7-bd2b-11e8-8256-41a843575de5 < BaseClient._make_api_call 1: 49.919s (8.075s in process) | |
| [INFO] 2018-09-20T23:16:02.100Z 05ecabb7-bd2b-11e8-8256-41a843575de5 ses.send_raw_email response: {'MessageId': '01000165f944d1b3-d8fcf13d-3e80-4bb5-9e57-198ff1a3306d-000000', 'ResponseMetadata': {'RequestId': '2362a206-bd2b-11e8-85ce-0b416c984dbe', 'HTTPStatusCode': 200, 'HTTPHeaders': {'x-amzn-requestid': '2362a206-bd2b-11e8-85ce-0b416c984dbe', 'content-type': 'text/xml', 'content-length': '338', 'date': 'Thu, 20 Sep 2018 23:16:01 GMT'}, 'RetryAttempts': 0}} | |
| END RequestId: 05ecabb7-bd2b-11e8-8256-41a843575de5 | |
| REPORT RequestId: 05ecabb7-bd2b-11e8-8256-41a843575de5 Duration: 49930.82 ms Billed Duration: 50000 ms Memory Size: 256 MB Max Memory Used: 174 MB |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment