Learning Lambda — Part 3

Starting to explore

This is Part 3 of Learning Lambda, a tutorial series about engineering using AWS Lambda. To see the other articles in this series please visit the series home page. To be alerted about future installments subscribe to our newsletter, follow Symphonia on twitter @symphoniacloud, and our blog at The Symphonium.

Welcome to part 3 of Learning Lambda! If you didn’t read part 2 you’ll probably want to do that before continuing here.

Last time we ended on something of a cliff hanger. We successfully executed a Lambda function but it had a sniff of magic about it. What happened? How did we make it happen?

In this part of Learning Lambda we’ll go over some basics about how Lambda code is executed in the the JVM rumtime, and then we’ll start to investigate what the Lambda environment looks like.

The lifecycle of a Lambda function

In part 2 we created a new Lambda function definition, using the AWS Lambda console. We gave it a name, we specified that it was to use a Java runtime, we told it what the handler function name, or entry point, was (io.symphonia.SimplestLambda::handler), we set up some security requirements, and we actually uploaded the code.

Finally we hit the Test button, and lo-and-behold, our function executed and its output was visible on the console. But what did AWS do when we hit the Test button to make this happen?

AWS Lambda is a ‘Functions-as-a-Service’ (FaaS) platform. We give the platform a function to run, and it does so on our behalf. Lambda accomplishes this by first creating a container for our function, on demand, whenever it needs to execute the function. So when we hit Test for the first time Lambda spun-up an actual Linux-hosted container. Where and how that container is instantiated is completely opaque to us. We know it’s somewhere in the AWS region we configured but that’s about all. The point here is that we never provisioned, allocated or configured a server, or host instance, for our code to run on, and nor can we. This is entirely AWS’ responsibility and decision.

Once the container is running Lambda then launches a ‘runtime’ — in our case within a Java 8 virtual machine (JVM). The initial code (‘main method’) run by the JVM is all Amazon’s and also part of the Lambda runtime — we still haven’t reached our logic yet.

Once the Java runtime is ready the Lambda platform calls it with an event. In this case the event is the simple String we specified in our test event(e.g. "world"). The Java runtime then instantiates the class encapsulating our handler function, and calls the function with the event as an argument.

And finally we’re in our code! For the SimplestLambda function we wrote in part 2 we create a new String and write this to System.out. AWS Lambda captures that output, and we’ll talk about that in just a moment.

Once our code has finished doing whatever it needs to do the handler function completes. The Java runtime takes the handler function response and returns it to the Lambda platform. In our case we wrote a void function, so the return value is expressed as null. The Lambda console, acting as a test harness, then displays that value on the page in the Execution result panel.

And that’s the lifecycle of a Lambda function — not magic after all!

Logging

As we mentioned a moment ago the Lambda runtime captures anything written by our function to the Standard Output (System.out in Java terms) or Standard Error streams. The runtime sends this content to CloudWatch Logs — the standard AWS logging service. The Lambda console displays the last few lines of these logs in the Log output panel.

If you have more than a few lines of logs you can see the complete output from your function by clicking the Click here link in the Log output panel, which will take you to the correct area of the CloudWatch logs console.

While you can just write to Standard Output using the methods on the System.out object it’s much more typical to use a logging framework to do so. We at Symphonia have created a very small library, lambda-logging, to provide a clean logging setup for Java Lambdas, and I’m going to introduce that below since it will help with what comes next. My colleague John Chapin has already written a much more complete article on this, which you can read here.

To add the logging library to our project we’re going to need to update the Maven pom.xml file. Open it up, and add the following section somewhere under the root node:

For those of you that know something about Java logging what this library does is provide SLF4J as a logging facade (an interface that we write our code to) and also includes Logback as the actual logging implementation. Finally it provides a default (overridable) Logback configuration that writes to Standard Output in a useful way for Lambdas.

With lambda-logging set up, we can now use it. I’m going to create a new Java class, copying the SimplestLambda class we made earlier and updating it to use our logging library:

The Lambda Java runtime places no restrictions on what libraries we use in our code, so depending on external libraries is as easy as this — we just import them as usual.

As we did in part 2 I’ll build this by running mvn package. This creates an uberjar with our code and the logging libraries we’re depending on. Remember that work we did with the Maven Shade plugin? That’s paying off now.

Next up I’m going to configure a new Lambda function in the AWS console, doing the same thing as I did before. Two differences this time:

• The handler name is now io.symphonia.LoggingLambda::handler
• When configuring the role, leave the first dropdown as Choose Existing Role, and then pick lambda_basic_execution in the next dropdown

Finally I’m going to execute this function using the same test event as last time ("world"). This runs, and we see the output from our function now looks like this:

[2017-02-15 19:43:03.185] f6571bdc-f3b6-11e6-ba02-35d3097a6e47 INFO i.s.LoggingLambda - Hello, world

The format of the message we see on this line is the result of Symphonia’s lambda-logging default configurator, including the time the log line was written, the AWS Request ID of the Lambda event, the log level, the class name of our handler, and finally the String we created.

There’s more to learn about Lambda Logging which you can read about in John’s article, or you can look at the source for our logging library here.

Introspecting our environment

Finally for this part we’re going to investigate what Amazon are giving us as an operating environment. Note that this part isn’t necessary for writing Lambdas but it does provide some interesting background info.

First of all we’re going to decrease the detail of our logging output by overriding the default configuration of lambda-logging. When debugging production systems it’s good to have all the details we just saw, but for this current kind of investigation we’re doing at the moment we just want to see what we’re writing out from our function.

To do this, create a logback.xml file in the src/main/resources directory of your project with the following contents:

Now we’re going to update our LoggingLambda Java class, as follows:

What we’re doing here is using the JVM Management Interface RuntimeMXBean to query for various pieces of runtime information. Looking at this code you’ll see we’re looking for details about the JVM, including memory information; how many CPU cores we have available; all the input arguments that were set by AWS when the JVM was started, which tells us, for example, what Garbage Collector settings we have; the classpath; and finally all the various system properties that are set.

After building this code go back to the Lambda console and hit the Upload button under the Code tab. Here you can upload the new version of the learning-lambda-1.0-SNAPSHOT.jar file.

After that click the Save and Test button and wait for Lambda to do its thing.

Assuming execution is successful you’ll see a lot more output in the Log output panel than we did before, and that’s not even all of our output. To see that you’ll need to click the Click here link to open up the CloudWatch Logs console. Click on the most recent log stream (which should be on the top of the list) — you should now see output for all the log lines we have in our class.

jvm name = [OpenJDK 64-Bit Server VM]  
jvm vendor = [Oracle Corporation]  
jvm version = [25.121-b13]  
jvm free memory = [55648864]  
jvm max memory = [441974784]  
jvm total memory = [60817408]  
jvm available processors = [2]  
jvm input argument = [-XX:MaxHeapSize=445645k]  
...

You can spend a few minutes looking at this output yourself, but there are a few things I want to point out:

• The number of processors available is 2. At time of writing that’s the number we always see, no matter what memory size or runtime you selected for your function.
• The max heap size is a little less than the memory you selected — that’s to allow for all other memory requirements. Recent analysis by us shows that the MaxHeap setting is always 85% of the total memory you configured for your Lambda, but AWS may change that at any time as they see fit.
• The os.version system property corresponds to the same as that in the AMI (Amazon Machine Image) that AWS make available for you to test with, should you desire. (See more detail here.)
• The java.version system property is 1.8.0_121, as we would expect.

Next time

That brings us to the end of Part 3 of this series. In Part 4 we look in much more detail at the input and output of a Lambda function, and what information you can get about a Lambda’s context. You can read that here.

To see the other articles in this series please visit the series home page. To be alerted about future installments subscribe to our newsletter, follow Symphonia on twitter @symphoniacloud, and our blog at The Symphonium.

Need help with Lambda, or other Serverless technologies? We’re the experts! Contact us at Symphonia for expert advice, architectural review, training, and on-team development.