Initial profiling annotations

.gitignore

@@ -121,4 +121,11 @@ node_modules/
 .vscode/
 
 # out files
-*.out
+*.out
+
+# Profiling
+*.prof
+
+# GraphViz
+*.png
+*.dot

README.md

@@ -67,6 +67,9 @@ This is the 40 digit sha1 commit hash for the code.  This is available in the gi
 ### APP_VERSION
 This is the `git describe --abbrev=7` value, useful for describing the code version.  This is available in the git repo as well as when deployed to AWS Lambda.
 
+### PROFILING_ENABLED
+This is the Boolean flag to indicate if profiling is enabled in the application.
+
 ## doit
 http://pydoit.org/
 
@@ -168,3 +171,8 @@ This run the `serverless deploy` command and requires the user to be logged into
 ```
 doit deploy
 ```
+
+## Postman
+
+A [Postman](https://www.getpostman.com/) URL collection is available for testing, learning, 
+etc [here](https://www.getpostman.com/collections/ab233178aa256e424668).

dodo.py

@@ -51,6 +51,7 @@ def envs(sep=' ', **kwargs):
         NEW_RELIC_TRUSTED_ACCOUNT_ID=CFG.NEW_RELIC_TRUSTED_ACCOUNT_ID,
         NEW_RELIC_SERVERLESS_MODE_ENABLED=CFG.NEW_RELIC_SERVERLESS_MODE_ENABLED,
         NEW_RELIC_DISTRIBUTED_TRACING_ENABLED=CFG.NEW_RELIC_DISTRIBUTED_TRACING_ENABLED,
+        PROFILING_ENABLED=CFG.PROFILING_ENABLED,
     )
     return sep.join([
         f'{key}={value}' for key, value in dict(envs, **kwargs).items()

services/fxa/serverless.yml

@@ -37,6 +37,7 @@ provider:
     NEW_RELIC_TRUSTED_ACCOUNT_ID: ${env:NEW_RELIC_TRUSTED_ACCOUNT_ID}
     NEW_RELIC_SERVERLESS_MODE_ENABLED: ${env:NEW_RELIC_SERVERLESS_MODE_ENABLED}
     NEW_RELIC_DISTRIBUTED_TRACING_ENABLED: ${env:NEW_RELIC_DISTRIBUTED_TRACING_ENABLED}
+    PROFILING_ENABLED: ${env:PROFILING_ENABLED}
     USER_TABLE:
       Ref: 'Users'
     EVENT_TABLE:

subhub/api/payments.py

@@ -1,4 +1,5 @@
 from datetime import datetime
+
 import stripe
 from flask import g
 
@@ -6,6 +7,7 @@ from subhub.api.types import JsonDict, FlaskResponse, FlaskListResponse
 from subhub.customer import existing_or_new_customer, has_existing_plan
 from subhub.exceptions import ClientError
 from subhub.log import get_logger
+from subhub.tracing import timed
 
 logger = get_logger()
 
@@ -278,6 +280,7 @@ def update_payment_method(uid, data) -> FlaskResponse:
         return {"message": "Customer mismatch."}, 400
 
 
+@timed
 def customer_update(uid) -> tuple:
     """
     Provide latest data for a given user
@@ -299,6 +302,7 @@ def customer_update(uid) -> tuple:
         return {"message": f"Customer does not exist: missing {e}"}, 404
 
 
+@timed
 def create_update_data(customer) -> dict:
     """
     Provide readable data for customer update to display

subhub/api/version.py

@@ -1,6 +1,5 @@
 from subhub.cfg import CFG
 from subhub.api.types import FlaskResponse
-
 from subhub.log import get_logger
 
 logger = get_logger()

subhub/auth_validation.py

@@ -1,10 +1,12 @@
 from subhub import secrets
 from subhub.cfg import CFG
 from subhub.log import get_logger
+from subhub.tracing import timed
 
 logger = get_logger()
 
 
+@timed
 def payment_auth(api_token, required_scopes=None):
     logger.info(f"api token {api_token}")
     if api_token in (CFG.PAYMENT_API_KEY,):
@@ -12,6 +14,7 @@ def payment_auth(api_token, required_scopes=None):
     return None
 
 
+@timed
 def support_auth(api_token, required_scopes=None):
     logger.info(f"api token {api_token}")
     if api_token in (CFG.SUPPORT_API_KEY,):
@@ -19,6 +22,7 @@ def support_auth(api_token, required_scopes=None):
     return None
 
 
+@timed
 def webhook_auth(api_token, required_scopes=None):
     logger.info(f"api token {api_token}")
     if api_token in (CFG.WEBHOOK_API_KEY,):

subhub/cfg.py

@@ -2,7 +2,7 @@
 """
 config
 """
-
+import ast
 import os
 import re
 import pwd
@@ -411,14 +411,14 @@ class AutoConfigPlus(AutoConfig):  # pylint: disable=too-many-public-methods
         """
         NEW_RELIC_ACCOUNT_ID
         """
-        return self("NEW_RELIC_ACCOUNT_ID", 2239138)
+        return self("NEW_RELIC_ACCOUNT_ID", 2_239_138)
 
     @property
     def NEW_RELIC_TRUSTED_ACCOUNT_ID(self):
         """
         NEW_RELIC_TRUSTED_ACCOUNT_ID
         """
-        return self("NEW_RELIC_TRUSTED_ACCOUNT_ID", 2239138)
+        return self("NEW_RELIC_TRUSTED_ACCOUNT_ID", 2_239_138)
 
     @property
     def NEW_RELIC_SERVERLESS_MODE_ENABLED(self):
@@ -434,6 +434,13 @@ class AutoConfigPlus(AutoConfig):  # pylint: disable=too-many-public-methods
         """
         return self("NEW_RELIC_DISTRIBUTED_TRACING_ENABLED", True)
 
+    @property
+    def PROFILING_ENABLED(self):
+        """
+        PROFILING_ENABLED
+        """
+        return ast.literal_eval(self("PROFILING_ENABLED", "False"))
+
     def __getattr__(self, attr):
         """
         getattr

subhub/customer.py

@@ -5,10 +5,12 @@ from subhub.exceptions import IntermittentError, ServerError
 from stripe.error import InvalidRequestError
 from subhub.subhub_dynamodb import SubHubAccount
 from subhub.log import get_logger
+from subhub.tracing import timed
 
 logger = get_logger()
 
 
+@timed
 def create_customer(
     subhub_account: SubHubAccount,
     user_id: str,
@@ -64,6 +66,7 @@ def create_customer(
     return customer
 
 
+@timed
 def existing_or_new_customer(
     subhub_accouunt: SubHubAccount,
     user_id: str,
@@ -81,6 +84,7 @@ def existing_or_new_customer(
     return existing_payment_source(customer_id, source_token)
 
 
+@timed
 def existing_payment_source(customer_id: str, source_token: str) -> stripe.Customer:
     existing_customer = stripe.Customer.retrieve(customer_id)
     if not existing_customer["sources"]["data"]:
@@ -89,6 +93,7 @@ def existing_payment_source(customer_id: str, source_token: str) -> stripe.Custo
     return existing_customer
 
 
+@timed
 def subscribe_customer(customer: stripe.Customer, plan_id: str) -> stripe.Subscription:
     """
     Subscribe Customer to Plan
@@ -99,6 +104,7 @@ def subscribe_customer(customer: stripe.Customer, plan_id: str) -> stripe.Subscr
     return stripe.Subscription.create(customer=customer, items=[{"plan": plan_id}])
 
 
+@timed
 def has_existing_plan(user: stripe.Customer, plan_id: str) -> bool:
     """
     Check if user has the existing plan in an active or trialing state.

subhub/log.py

@@ -30,7 +30,6 @@ import structlog
 
 from subhub.cfg import CFG
 
-
 IS_CONFIGURED = False
 EVENT_UUID = str(uuid.uuid4())
 LOGGING_CONFIG = {

subhub/subhub_dynamodb.py

@@ -3,6 +3,8 @@ from typing import Optional
 from pynamodb.attributes import UnicodeAttribute, ListAttribute
 from pynamodb.models import Model, DoesNotExist
 from pynamodb.exceptions import PutError
+from subhub.tracing import timed, cprofiled
+
 from subhub.log import get_logger
 
 logger = get_logger()
@@ -40,6 +42,7 @@ class SubHubAccount:
     ) -> SubHubAccountModel:
         return self.model(user_id=uid, cust_id=cust_id, origin_system=origin_system)
 
+    @timed
     def get_user(self, uid: str) -> Optional[SubHubAccountModel]:
         try:
             subscription_user = self.model.get(uid, consistent_read=True)

subhub/tracing.py

@@ -0,0 +1,89 @@
+import time
+import cProfile
+from subhub.cfg import CFG
+
+from functools import wraps
+
+"""
+Memory Profile a function
+Requires the environment variable, PYTHONTRACEMALLOC to be set prior 
+or you will get the following run-tine exception:
+    `the tracemalloc module must be tracing memory allocations to take a snapshot`
+    
+Calling syntax:
+    @mprofiled
+    def some_function():
+        pass
+"""
+
+
+def mprofiled(func):
+    import tracemalloc
+    import os
+
+    def profiled(*args, **kwargs):
+        if not CFG.PROFILING_ENABLED:
+            return func(*args, **kwargs)
+        else:
+            if "PYTHONTRACEMALLOC" not in os.environ:
+                os.environ["PYTHONTRACEMALLOC"] = "1"
+            tracemalloc.start()
+            memory_before = tracemalloc.take_snapshot()
+            result = func(*args, **kwargs)
+            memory_after = tracemalloc.take_snapshot()
+            top_stats = memory_after.compare_to(memory_before, "lineno")
+            for stat in top_stats[:10]:
+                print(stat)
+            tracemalloc.stop()
+            return result
+
+    return profiled
+
+
+"""
+cProfile of a provided function.
+Calling syntax:
+    @cprofiled
+    def some_function():
+        pass
+"""
+
+
+def cprofiled(func):
+    def profiled(*args, **kwargs):
+        if not CFG.PROFILING_ENABLED:
+            return func(*args, **kwargs)
+        else:
+            profile = cProfile.Profile()
+            try:
+                profile.enable()
+                result = func(*args, **kwargs)
+                profile.disable()
+                return result
+            finally:
+                profile.print_stats()
+
+    return profiled
+
+
+"""
+Elapsed timing of a provided function.
+Calling syntax;
+    @timed
+    def some_function():
+        passs
+"""
+
+
+def timed(function):
+    def timer(*args, **kwargs):
+        if not CFG.PROFILING_ENABLED:
+            return function(*args, **kwargs)
+        else:
+            start = time.time()
+            result = function(*args, **kwargs)
+            end = time.time()
+            print(function.__name__, "took", end - start, "time")
+            return result
+
+    return timer