Writing EMF metrics significantly increases lambda execution time

[tgip-work]

I am using the metrics functionality of the Lambda Powertools for generating custom Cloudwatch metrics (via writing EMF records into Cloudwatch logs).
The overall execution time of our Lambda functions has significantly increased since we are using the Powertools.
With "significantly" I mean approx. 50 to 100ms per metric on a 128 MB lambda function.

Expected Behavior

Adding metrics should only increase the execution time of a Lambda function by < 1ms per metric.

Current Behavior

Each metric added increases execution time by approx. 50 to 100ms on a Lambda function running with 128MB of RAM.

Possible Solution

I drilled down the code and guess that the schema validation is causing the performance issue. See [code] (https://github.com/awslabs/aws-lambda-powertools-python/blob/develop/aws_lambda_powertools/metrics/base.py#L214).

Possible solutions:

1. Offer option to disable/skip validation
2. Precompile the schema and keep validation object in a global variable/scope so it can be reused - see https://horejsek.github.io/python-fastjsonschema/

Steps to Reproduce (for bugs)

from aws_lambda_powertools import Metrics
from aws_lambda_powertools.metrics import MetricUnit
metrics = Metrics(namespace="Company/Product", service="some-service")

@metrics.log_metrics(capture_cold_start_metric=True)
def lambda_handler(event, context):
    metrics.add_metric(name="Ok", unit=MetricUnit.Count, value=1)
    metrics.add_metric(name="Errors", unit=MetricUnit.Count, value=1)

Environment

• Powertools version used: 1.10.5
• Packaging format (Layers, PyPi): PyPi
• AWS Lambda function runtime: Python 3.6 and also Python 3.8 with 128 MB RAM
• Debugging logs

How to enable debug mode**

2021-03-03T11:28:05.105+01:00 START RequestId: 20607f86-e159-4f0e-a89b-7298f2ddbbed Version: $LATEST
[INFO]	2021-03-03T10:28:05.105Z		Found credentials in environment variables.
2021-03-03 10:28:05,229 aws_lambda_powertools.metrics.metrics [DEBUG] Decorator called with parameters
2021-03-03 10:28:05,275 aws_lambda_powertools.metrics.base [DEBUG] Adding metric: RecordsInserted with defaultdict(<class 'list'>, {'Unit': 'Count', 'Value': [1.0]})
2021-03-03 10:28:05,278 aws_lambda_powertools.metrics.metrics [DEBUG] Adding cold start metric and function_name dimension
2021-03-03 10:28:05,279 aws_lambda_powertools.metrics.base [DEBUG] Adding metric: ColdStart with defaultdict(<class 'list'>, {'Unit': 'Count', 'Value': [1.0]})
2021-03-03 10:28:05,279 aws_lambda_powertools.metrics.base [DEBUG] Adding dimension: function_name:my-function
2021-03-03 10:28:05,279 aws_lambda_powertools.metrics.base [DEBUG] Adding dimension: service:my-service
2021-03-03 10:28:05,279 aws_lambda_powertools.metrics.base [DEBUG] {'details': 'Serializing metrics', 'metrics': {'ColdStart': defaultdict(<class 'list'>, {'Unit': 'Count', 'Value': [1.0]})}, 'dimensions': {'function_name': 'my-function', 'service': 'my-service'}}
2021-03-03 10:28:05,279 aws_lambda_powertools.metrics.base [DEBUG] Validating serialized metrics against CloudWatch EMF schema
2021-03-03T11:28:05.398+01:00
{
    "_aws": {
        "Timestamp": 1614767285279,
        "CloudWatchMetrics": [
            {
                "Namespace": "Company/Product",
                "Dimensions": [
                    [
                        "function_name",
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "ColdStart",
                        "Unit": "Count"
                    }
                ]
            }
        ]
    },
    "function_name": "my-function",
    "service": "my-service",
    "ColdStart": [
        1
    ]
}
2021-03-03 10:28:05,398 aws_lambda_powertools.metrics.base [DEBUG] {'details': 'Serializing metrics', 'metrics': {'RecordsInserted': defaultdict(<class 'list'>, {'Unit': 'Count', 'Value': [1.0]})}, 'dimensions': {'service': 'my-service'}}
2021-03-03 10:28:05,398 aws_lambda_powertools.metrics.base [DEBUG] Validating serialized metrics against CloudWatch EMF schema
2021-03-03 10:28:05,498 aws_lambda_powertools.metrics.metrics [DEBUG] Clearing out existing metric set from memory
2021-03-03T11:28:05.498+01:00
{
    "_aws": {
        "Timestamp": 1614767285398,
        "CloudWatchMetrics": [
            {
                "Namespace": "Company/Product",
                "Dimensions": [
                    [
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "RecordsInserted",
                        "Unit": "Count"
                    }
                ]
            }
        ]
    },
    "service": "my-service",
    "RecordsInserted": [
        1
    ]
}
END RequestId: 20607f86-e159-4f0e-a89b-7298f2ddbbed

[heitorlessa]

Hey @tgip-work - thanks for the detailed issue.

Question: Do you see the behaviour consistently in non-cold start executions?

Last I remember checking fastjsonschema the cold start validation and serialisation was roughly 25ms, and single digit thereafter (mostly JSON Serialisation).

If that however is happening even after cold start then it's a problem I'd like to prioritise to our next release (big one already).

Thanks

[tgip-work]

Hi @heitorlessa ,

thanks for your quick reply.
This also happens on non-coldstart executions. It does not seem to matter if cold or warm.

[heitorlessa]

Understood, thank you! While I don't think we can get to <1 ms because of how JSON works in python, uJSON could but that would be another dep.... we can surely decrease this time with a few perf improvements.

I'll post an update this week on how far I get. Meantime, I've also finished this optimization that will be available in the next release on import times - Specially if you don't use Tracer (75% improvement).

#301 (comment)

[heitorlessa]

Initial perf test on my local machine (8 core, 32G RAM):

Scenario: Add and serialize 99 metrics, one dimension, and namespace

• JSON Schema validation (as-is): 25ms
• No validation: 100 microseconds
• Native python validation: TBW

Fair to say we might be able reach <1ms indeed @tgip-work !! I'll experiment with native Python validation and keep you posted

---

@pytest.mark.perf
def test_metrics_validation_sla(namespace, dimension, ninety_nine_metrics):
    # GIVEN Metrics is initialized
    my_metrics = Metrics(namespace=namespace)
    my_metrics.add_dimension(**dimension)

    # WHEN we add 99 metrics
    for _metric in ninety_nine_metrics:
        my_metrics.add_metric(**_metric)

    with timing() as t:
        my_metrics.serialize_metric_set()

    elapsed = t()
    if elapsed > METRICS_VALIDATION_SLA:
        pytest.fail(f"Meh, can't let @tgip-work, at least below 10ms we should do it...: {elapsed}")

[tgip-work]

Hi @heitorlessa : Yes, great work. This looks very promising! Happily looking forward for the next release :-)

[heitorlessa]

Turns out my test was wrong - I've converted from JSON Schema validation (~25ms) to Native Python (500-700usec), however, what was missing in the test was JSON Serialization.

Adding JSON Serialization and printing the metrics makes us fail the goal of <1ms as we go from microseconds to ~7ms in total.

IF we add ujson we easily reach <1ms, including other utilities that need JSON serialization like the upcoming idempotence will benefit from that, HOWEVER it'll increase the package size by 1M.

I honestly think it's a great tradeoff, and that even means customers could benefit from that too since that will be installed in their Lambda functions -- Allow me to consult with the rest of the team to check on that.

Worst case, we'll go from ~25ms to <10ms without having to even disable validation.

Thanks

[tgip-work]

Hi @heitorlessa,
have you tried serializing into compacted JSON: json.dumps(data, separators=(',', ':'))
This reduces the length of the generated string and should improve performance a little bit.

I am absolutely fine with reduced execution time if it is also possible to turn of validation as you already implemented as an option in your changes