Evaluate internal WARM performance of LambdaSwiftSprinterNioPlugin with HelloWorld

[Andrea-Scuderi]

We want to provide some context on the internal performance when the Lambda is Warm

HelloWorld example:

import AsyncHTTPClient
import Foundation
#if canImport(FoundationNetworking)
    import FoundationNetworking
#endif
import LambdaSwiftSprinter
import LambdaSwiftSprinterNioPlugin

enum MyError: Error {
    case unableToConvertString
}

class Lambda: LambdaHandler {
    func commonHandler(event: Data, context: Context) -> LambdaResult {
        guard let data = "Hello World!".data(using: .utf8) else {
            return .failure(MyError.unableToConvertString)
        }
        return .success(data)
    }
}

let lambda = Lambda()

public func log(_ object: Any, flush: Bool = false) {
    fputs("\(object)\n", stderr)
    if flush {
        fflush(stderr)
    }
}

do {
    let sprinter = try SprinterNIO()
    sprinter.register(handler: "helloWorld", lambda: lambda)
    try sprinter.run()
} catch {
    log(String(describing: error))
}

Note Data and Context are not used, but are being passed to the lambda function.

Using AWS Lambda with 256MB the warm performance is around ~1.19ms.

We want to evaluate where the execution time is spent

The main loop when the lambda is warm is contained in the following file: https://github.com/swift-sprinter/aws-lambda-swift-sprinter-core/blob/master/Sources/LambdaSwiftSprinter/Sprinter.swift

public func run() throws {
        while !cancel {
            let (event, responseHeaders) = try apiClient.getNextInvocation()
            counter += 1

            if let lambdaRuntimeTraceId = responseHeaders.rhk(key: .runtimeTraceId) {
                setenv(Context.AWSEnvironmentKey.xAmznTraceId.rawValue, lambdaRuntimeTraceId, 0)
            }

            guard let lambda = lambdas[handlerName] else {
                try apiClient.postInitializationError(error: SprinterError.missingEnvironmentVariables(.handler))
                return
            }

            let context = try Context(environment: environment, responseHeaders: responseHeaders)
            let result = lambda.commonHandler(event: event, context: context)

            switch result {
            case .success(let outputData):
                try apiClient.postInvocationResponse(for: context.awsRequestId, httpBody: outputData)
            case .failure(let error):
                try apiClient.postInvocationError(for: context.awsRequestId, error: error)
            }
        }
    }

The getNextInvocation() is implemented in https://github.com/swift-sprinter/aws-lambda-swift-sprinter-nio-plugin/blob/master/Sources/LambdaSwiftSprinterNioPlugin/LambdaApiNIO.swift

public func getNextInvocation() throws -> (event: Data, responseHeaders: [AnyHashable: Any]) {
        let result = try httpClient.execute(
            request: _nextInvocationRequest,
            deadline: nil
        ).wait()

        let httpHeaders = result.headers

        guard result.status.isValid() else {
            throw SprinterNIOError.invalidResponse(result.status)
        }

        if let body = result.body,
            let data = body.getData(at: 0,
                                    length: body.readableBytes,
                                    byteTransferStrategy: .noCopy) {
            return (event: data, responseHeaders: httpHeaders.dictionary)
        } else {
            throw SprinterNIOError.invalidBuffer
        }
    }

Note that the Lambda remains in waiting for the next event while calling getNextInvocation() in the run loop until is killed or the timeout of 3600s is triggered.

We want understand if some optimisation can improve the performance Reference Golang with a performance at warm of ~0.44 ms.

package main

import "github.com/aws/aws-lambda-go/lambda"

type Response struct {
    StatusCode      int    `json:"statusCode"`
    Body            string `json:"body"`
    IsBase64Encoded bool   `json:"isBase64Encoded"`
}

func hello() (Response, error) {
    return Response{
        StatusCode:      200,
        Body:            "Hello world",
        IsBase64Encoded: false,
    }, nil
}

func main() {
    lambda.Start(hello)
}

[Andrea-Scuderi]

Adding the following code:

Sprinter.swift

internal let info = ProcessInfo.processInfo
internal var begin = info.systemUptime

internal func log(_ object: Any, flush: Bool = false) {
    let diff = (info.systemUptime - begin)*1000
    fputs("core: \(diff)ms: \(object)\n", stderr)
    if flush {
        fflush(stderr)
    }
    begin = info.systemUptime
}

//...
public func run() throws {

        while !cancel {
            log("wait")
            let (event, responseHeaders) = try apiClient.getNextInvocation()
            counter += 1
            log("getNextInvocation")

            if let lambdaRuntimeTraceId = responseHeaders.rhk(key: .runtimeTraceId) {
                setenv(Context.AWSEnvironmentKey.xAmznTraceId.rawValue, lambdaRuntimeTraceId, 0)
            }
            log("lambdaRuntimeTraceId")

            guard let lambda = lambdas[handlerName] else {
                try apiClient.postInitializationError(error: SprinterError.missingEnvironmentVariables(.handler))
                return
            }
            log("lambdas[handlerName]")

            let context = try Context(environment: environment, responseHeaders: responseHeaders)
            log("context")
            let result = lambda.commonHandler(event: event, context: context)
            log("commonHandler")
            switch result {
            case .success(let outputData):
                try apiClient.postInvocationResponse(for: context.awsRequestId, httpBody: outputData)
                log("postInvocationResponse")
            case .failure(let error):
                try apiClient.postInvocationError(for: context.awsRequestId, error: error)
                log("postInvocationError")
            }
        }
    }

and to LambdaApiNIO.swift

internal let info = ProcessInfo.processInfo
internal var begin = info.systemUptime

internal func log(_ object: Any, flush: Bool = false) {
    let diff = (info.systemUptime - begin)*1000
    fputs("   nio-plugin: \(diff)ms:\(object)\n", stderr)
    if flush {
        fflush(stderr)
    }
    begin = info.systemUptime
}

func reset() {
    begin = info.systemUptime
}

//...
public func getNextInvocation() throws -> (event: Data, responseHeaders: [AnyHashable: Any]) {
        reset()
        let result = try httpClient.execute(
            request: _nextInvocationRequest,
            deadline: nil
        ).wait()
        log("httpClient.execute")

        let httpHeaders = result.headers

        guard result.status.isValid() else {
            throw SprinterNIOError.invalidResponse(result.status)
        }
        log("result.status.isValid()")

        if let body = result.body,
            let data = body.getData(at: 0,
                                    length: body.readableBytes,
                                    byteTransferStrategy: .noCopy) {
                                        log("body.getData(at:...)")
            return (event: data, responseHeaders: httpHeaders.dictionary)
        } else {
            throw SprinterNIOError.invalidBuffer
        }
    }

//...

public func postInvocationResponse(for requestId: String, httpBody: Data) throws {
        reset()
        var request = try HTTPClient.Request(
            url: urlBuilder.invocationResponseURL(requestId: requestId),
            method: .POST
        )
        request.body = .data(httpBody)
        log(".data(httpBody)")
        _ = try httpClient.execute(
            request: request,
            deadline: nil
        ).wait()
        log("httpClient.execute")
    }

The result is:

START RequestId: 8e120434-2108-4a59-9bb4-956b6a6b5e84 Version: $LATEST
   nio-plugin: 1065.549714000099ms:httpClient.execute
   nio-plugin: 0.00033700007406878285ms:result.status.isValid()
   nio-plugin: 0.003169000137859257ms:body.getData(at:...)
core: 1065.6208529999276ms: getNextInvocation
core: 0.008160000106727239ms: lambdaRuntimeTraceId
core: 0.000874000306794187ms: lambdas[handlerName]
core: 0.008774999969318742ms: context
core: 0.005031999990023905ms: commonHandler
   nio-plugin: 0.05818800036649918ms:.data(httpBody)
   nio-plugin: 0.488504999793804ms:httpClient.execute
core: 0.5696690000149829ms: postInvocationResponse
core: 0.0049599998419580515ms: wait
END RequestId: 8e120434-2108-4a59-9bb4-956b6a6b5e84
REPORT RequestId: 8e120434-2108-4a59-9bb4-956b6a6b5e84  Duration: 1.42 ms   Billed Duration: 100 ms Memory Size: 256 MB Max Memory Used: 84 MB  

The difficult part is to evaluate the getNextInvocation as the Lambda run in a loop. In the log getNextInvocation contains the between two different lambda calls.

Total time: 1.42 Time after next invocation: 0.59747

getNextInvocation = 1.42 - 0.59747 = 0.82253

The time is consumed mostly in: getNextInvocation = 0.82253ms postInvocationResponse = 0.5696690000149829ms

This suggest to try an HelloWorld go with a parameter Data/Context to check if there is any difference.

[Andrea-Scuderi]

Test changing the go example with the context

package main

import (
    "context"
    "github.com/aws/aws-lambda-go/lambda"
)

type Input struct {

}

type Response struct {
    StatusCode      int    `json:"statusCode"`
    Body            string `json:"body"`
    IsBase64Encoded bool   `json:"isBase64Encoded"`
}

func HandleRequest(ctx context.Context, data Input) (Response, error) {
    return Response{
        StatusCode:      200,
        Body:            "Hello world",
        IsBase64Encoded: false,
    }, nil
}

func main() {
        lambda.Start(HandleRequest)
}

Result:

START RequestId: 91e4b5fa-e661-4fca-84cf-398827c2805a Version: $LATEST
END RequestId: 91e4b5fa-e661-4fca-84cf-398827c2805a
REPORT RequestId: 91e4b5fa-e661-4fca-84cf-398827c2805a  Duration: 0.44 ms   Billed Duration: 100 ms Memory Size: 256 MB Max Memory Used: 32 MB  

The performance in go doesn't change by adding Data/Context

[t089]

Just dropping an idea here: If I read the current implementation correctly the lambda runs mostly "on the main thread" and .wait()s on the futures of the event loop from the AsyncHTTPClient event loop group. Maybe this incurs some "context switching penalty"?

I wonder if it would be possible to rewrite the Swift sprinter in a way to avoid any calls to .wait inside the processing code. So essentially getNextInvocation would return a EventLoopFuture<(Event, ResponseHeaders)> and then everything would happen on this event loop instead of moving back and forth between event loop thread and main thread.

[Andrea-Scuderi]

@t089 Thanks for the suggestion. Is it something different from what is implemented in this https://github.com/fabianfett/swift-lambda-runtime/blob/master/Sources/LambdaRuntime/Runtime.swift by @fabianfett ?

[t089]

Ah yes, actually this is pretty much what I had in mind. In the end we would need to do some profiling to see where the swift code spends too much time.

[t089]

Have you benchmarked @fabianfett's implementation as well?

[t089]

Have you benchmarked @fabianfett's implementation as well?

Ah yes, you did and it actually performed slightly worse...

[fabianfett]

@t089 I'm not sure if it was using the connection pooled AsyncHTTPClient already, which might explain the worse performance.

[Andrea-Scuderi]

@t089 Yes, I had. There is a penalty of ~0.20ms in the @fabianfett version. https://medium.com/better-programming/swift-on-aws-lambda-performs-like-node-and-python-using-swift-sprinter-d920521130f1

The value for that is in the lambda called al-swift-ffett-hello ~1.83ms (on Amazon Linux 2 - no connection pooling) vs al-swift-nio-hello ~1.61ms (swift-sprinter on Amazon Linux 2 - no connection pooling)

[Andrea-Scuderi]

@fabianfett happy to run the test again if you point me to the right implementation.

[fabianfett]

@Andrea-Scuderi So the task of the lambda is just to return "HelloWorld"? If it is okay for you I'll setup a small repo with a lambda doing just that?

[Andrea-Scuderi]

@fabianfett: Yes just HelloWorld

I used this code with your runtime:

import LambdaRuntime
import NIO

struct Input: Codable {
  let key: String?
}

struct Output: Codable {
  let result: String
}

func helloWorld(input: Input, context: Context) -> EventLoopFuture<Output> {
  return context.eventLoop.makeSucceededFuture(Output(result: "HelloWorld!"))
}

let group = MultiThreadedEventLoopGroup(numberOfThreads: 1)
defer { try! group.syncShutdownGracefully() }

do {
  let runtime = try Runtime.createRuntime(
    eventLoopGroup: group, 
    handler: Runtime.codable(helloWorld))

  defer { try! runtime.syncShutdown() }

  try runtime.start().wait()
}
catch {
  print("\(error)")
}

[fabianfett]

@Andrea-Scuderi @t089 Here you go: https://github.com/fabianfett/lambda-runtime-performance-test

I removed the JSON overhead and ByteBuffer directly, though that doesn't seem to make much of a difference. Excited to see the results.

[Andrea-Scuderi]

@fabianfett @t089 How I've already mention in the article there is no much difference between the two lambda frameworks compared to the overall duration.

Using connection pool we got similar result on both Swift-Sprinter and your runtime. I think the overall performance doesn't depends too much from the runtime.

Minimum Duration: swift-NIO-pooling-hello: 1.19 ms (Ubuntu) al-swift-ffett-pooling-hello: 1.19 ms (Amazon Linux 2) al-swift-nio-pooling-hello: 1.26 ms (Amazon Linux 2)

The difference between go and Swift seems due by the AsyncHTTPClient/NIO implementation.