I was curious what would happen with a time.Ticker running in an AWS Lambda function.

It was pretty obvious that the ticker wouldn’t tick while the container was hibernating, but what about when it woke up? Would a bunch of ticks happen if the container had been hibernating for a long time? Would you get a tick at all?

tl;dr

It looks like you get one tick when the function comes out of hibernation (assuming the ticker duration has passed at least once), and if the function never hibernates the ticks happen on time, which for my purposes is pretty much perfect.

The code

I set up a small AWS Lambda function that responds to API Gateway requests and has a goroutine running with a time.Ticker that ticks every minute:

package main

import (
  "context"
  "fmt"
  "net/http"
  "sync"
  "time"

  "github.com/aws/aws-lambda-go/events"
  "github.com/aws/aws-lambda-go/lambda"
)

func main() {
  wg := &sync.WaitGroup{}

  ticker := time.NewTicker(time.Second * 60)
  go func() {
    for t := range ticker.C {
      // let the WaitGroup know that we're working
      wg.Add(1)

      // tell the observer that the ticker actually ticked
      fmt.Println("tick at", t)
      
      // simulate a background process that takes a bit to complete
      time.Sleep(time.Second)
      
      // let the WaitGroup know that we're done
      wg.Done()
    }
  }()

  lambda.Start(func(ctx context.Context, req events.APIGatewayProxyRequest)(events.APIGatewayProxyResponse, error) {
    resp, err := realHandler(ctx, req)
    
    // If the ticker is running, wait for it.
    wg.Wait()

    return resp, err
  })
}

func realHandler(ctx context.Context, req events.APIGatewayProxyRequest) (events.APIGatewayProxyResponse, error) {
  return events.APIGatewayProxyResponse{
    StatusCode: http.StatusPaymentRequired,
  }, nil
}

You’ll see how I’ve split out the real handler and the ticker-waiting “middleware” … this keeps the handler logic separated from the bit that waits for the background goroutine to complete what it’s doing before returning.

The test

I called the function a couple of times, waited a few minutes, and called the function again. The logs told me what happened:

2020-11-02T14:11:51.061-05:00 START RequestId: f2604bb1-8bc2-445a-b7b2-3893d8d3416d Version: $LATEST
2020-11-02T14:11:51.063-05:00 END RequestId: f2604bb1-8bc2-445a-b7b2-3893d8d3416d
2020-11-02T14:11:51.063-05:00 REPORT RequestId: f2604bb1-8bc2-445a-b7b2-3893d8d3416d Duration: 1.39 ms Billed Duration: 100 ms Memory Size: 1024 MB Max Memory Used: 35 MB Init Duration: 66.79 ms XRAY TraceId: 1-5fa059f6-10e9a1715cb581111721b9a8 SegmentId: 0467a00a5d719145 Sampled: true

2020-11-02T14:11:54.171-05:00 START RequestId: 7a39872e-4b18-42da-b2ff-315a6590a1b6 Version: $LATEST
2020-11-02T14:11:54.174-05:00 END RequestId: 7a39872e-4b18-42da-b2ff-315a6590a1b6
2020-11-02T14:11:54.174-05:00 REPORT RequestId: 7a39872e-4b18-42da-b2ff-315a6590a1b6 Duration: 0.68 ms Billed Duration: 100 ms Memory Size: 1024 MB Max Memory Used: 42 MB XRAY TraceId: 1-5fa059fa-0be52e2845702dd0365eeb74 SegmentId: 5d5f37f527b7de1a Sampled: true

The first two log blocks show the first two calls, at 14:11:51-05:00 and at 14:11:54-05:00. We wouldn’t expect to see a tick log here, and as expected we do not.

2020-11-02T14:16:28.076-05:00 START RequestId: 488123cd-43bc-4567-9970-00c35bfc91b8 Version: $LATEST
2020-11-02T14:16:28.076-05:00 tick at 2020-11-02 19:16:28.076072523 +0000 UTC m=+277.052607202
2020-11-02T14:16:28.078-05:00 END RequestId: 488123cd-43bc-4567-9970-00c35bfc91b8
2020-11-02T14:16:28.078-05:00 REPORT RequestId: 488123cd-43bc-4567-9970-00c35bfc91b8 Duration: 0.59 ms Billed Duration: 100 ms Memory Size: 1024 MB Max Memory Used: 42 MB XRAY TraceId: 1-5fa05b0c-35afecef72dc3fb25cf4eeef SegmentId: 045243422ccaea72 Sampled: true

2020-11-02T14:20:15.133-05:00 START RequestId: 2dc415ef-f53f-4e35-865d-21b89cd9147e Version: $LATEST
2020-11-02T14:20:15.133-05:00 tick at 2020-11-02 19:20:15.133194003 +0000 UTC m=+504.107026404
2020-11-02T14:20:15.137-05:00 END RequestId: 2dc415ef-f53f-4e35-865d-21b89cd9147e
2020-11-02T14:20:15.137-05:00 REPORT RequestId: 2dc415ef-f53f-4e35-865d-21b89cd9147e Duration: 0.62 ms Billed Duration: 100 ms Memory Size: 1024 MB Max Memory Used: 43 MB XRAY TraceId: 1-5fa05bef-5e8453ea22ff3fa4454e0af6 SegmentId: 183982d42c0b3848 Sampled: true

The next two log blocks show calls at 14:16:28-05:00 and 14:20:15-05:00 and one tick happening each time the code is invoked. This would seem to indicate that even if multiple ticks would normally have happened in the time period, they are consolidated into one.

Neat!