Logging Costs

The scale of data processing coupled with the elasticity of cloud storage can create a perfect storm for data pipelines to generate massive amounts of log data.

I encountered this in a pipeline where logging doubled execution time and racked up thousands of dollars per month in cloud costs. The logging approach was developed for debugging single processes over a small dataset in a local environment. In this setting, there was no need to provide identifying information with the log messages, as there was only a single process running in debug. At scale, the logs were incomprehensible, having lost the context of which process was generating a given log message.

This was a worst-of-all-worlds situation; the abundance of logs severely impacted performance, driving up cloud costs due to both log data volume and increased execution time. On top of that, the logs weren’t created with scale in mind, so they not only were useless for debugging but also crowded out important log messages with all the noise.

Reducing Logging Costs

There are a variety of things you can do to reap the benefits of cloud logging while keeping costs in check, ranging from manipulating cloud service settings to utilizing logging techniques and tools for handling logs at scale.

Let’s start on the cloud services side. When you use cloud logging, typically the logs will be kept forever unless you configure a log retention period, such as described in the AWS article “Altering CloudWatch log retention”. Establishing a retention period will result in logs being removed after a specific duration, ensuring that you aren’t holding on to logs that are no longer of use.

Similar to the lifecycle policies you saw in Chapter 3, retention periods will vary across services and environments. For instance, retaining production logs for a week could be worthwhile for debug and monitoring. In a test environment, you’ll likely debug failures over a smaller window, making it cost-effective to use a shorter retention period.

In addition to the retention period, you can configure which logs to forward to the logging service and which to ignore. This can further reduce your logging footprint by homing in on just the logs of interest. For example, Google Cloud Logging gives you the ability to set exclusion and inclusion filters to this end.

In terms of logging techniques, making use of different log levels helps you tune log verbosity. The Python logging documentation includes an overview of when to use different log levels depending on the types of messages you want to convey. You can then select the level of logging in different environments. In a production environment, you may use the default level of WARNING to surface informational messages, warnings, and errors while suppressing debug messages. In a development or test environment, you can set the log level lower to DEBUG to get additional information.

For especially noisy modules, consider more granular control over logging. For example, in a test environment with a log level of DEBUG, you can introduce an additional flag to set the log level for a module that has verbose DEBUG logging. By default, you could set the module log level flag to INFO to reduce log messages. If circumstances warrant the additional logging, you can change the level, rather than constantly dealing with a flood of log messages that may not be useful.

Using configurations lets you change the log level without code changes. This approach also enables different logging levels across various environments. I’ve seen this done with environment variables, where a DEBUG flag was turned on for the test environment but disabled for production. If an issue came up in production, our team could enable debug logs with just a flip of an environment variable.

For Python in particular, you can reduce the performance impact of logging by delaying the creation of log messages. You can see in the Python logging flow that a logging record is created only if the logger is enabled for the log level of the logging call. If not, the log record doesn’t get created.

For example, here are two different approaches for logging a message with variables, one using % formatting and the other using f-strings:

logger.debug("Finished extracting species for user %s. Species extracted: %s", 
             user_id, species)

logger.debug(f"Finished extracting species for user {user_id}. 
              Species extracted: {species}")

Let’s consider what happens in an environment where the log level is set above DEBUG. In the f-strings case, the log message is interpolated before the call is made to logger.debug. Regardless of whether the logger actually creates the log record, this string will be created.

In the %s case, you’re passing the user_id and species as arguments to the logger.debug method. Instead of the string creation happening before the logger method is called, the string interpolation will be performed by the logging handler, only if the log level warrants it.

This may seem like small potatoes, but remember that these little things can add up at scale.

Another optimization from the Python logging cookbook is conditional logging. In this technique, logs are only emitted if a certain condition is met. This is a great way to limit logs that are primarily intended to help debug failures; if the failure doesn’t occur, the would-be log messages are pass:[dumped rather than written to the log. In the scenario I shared earlier where logging doubled pipeline runtime, conditional logging that emitted the diagnostic messages only if an error occurred would have eliminated most of the logs.

As with the example in the Python documentation, setting the capacity for the log buffer is a good practice to use memory judiciously. This will prevent wasting memory on buffered log messages.

The techniques you’ve seen in this section will help reduce log volume and help you surface only those log messages that are relevant in a given environment and situation. This both reduces costs and cuts down on log noise.

The next section switches the focus from log costs to creating logs that are effective at scale and can be leveraged by aggregation tools for analysis.

Effective Logging

When it comes to building for parallel execution, whether in a distributed system or in a parallel processing environment, it’s important to reconsider how to approach logging versus a centralized environment.

For example, when you have multiple processes or workers executing in parallel, your log messages need to contain some identifying information to help you determine what a log event refers to. Returning to the earlier Python logging example, notice that I included the user_id in this log message about species extraction:

logger.debug("Finished extracting species for user %s. Species extracted: %s", 
              user_id, species)

This log message would produce something like the following:

[DEBUG] Finished extracting species for user abc. Species extracted: night heron

Contrast this with the following messages, which lack this context. You can imagine how unhelpful a string of log messages such as these would be for root-causing an issue:

[INFO] Start extracting species
[INFO] Start extracting species
[ERROR] Failed extracting species
[INFO] Finish extracting species
[INFO] Finish extracting species

This was the state of the logs in the situation I shared in “Logging Costs”; without identifying information, the log messages couldn’t be correlated to the relevant process.

When crafting log messages, think about information you would want when debugging an issue, such as:

• The environment where the job is running

• The service or process executing the code

• Data identifiers, including IDs for the related batch, row, or event

Some of this information might be available as a consequence of how your infrastructure is set up. For example, a data platform I worked on that ran in Kubernetes used separate projects for each environment, so it wasn’t necessary to log this information. I could also get the service information from the name of the pods. If I wanted to look at logs in the Spark deployment on production, I opened the Logs Explorer in the production project and filtered by pod names matching “spark.”

Returning to the species extraction example, what if there were multiple rows of data for user abc?

[DEBUG] Finished extracting species for user abc. Species extracted: night heron
[DEBUG] Finished extracting species for user abc.  Species extracted: None

In this case, you don’t know what the description field looked like, so it’s hard to say whether the extraction is correct. Including row, batch, and event IDs in your logs can help disambiguate issues like this:

[DEBUG] Finished extracting species for user abc, batch 1, record 1-1.
        Species extracted: night heron
[DEBUG] Finished extracting species for user abc, batch 1, record 1-2.
        Species extracted: None

In addition to what you log, how you structure log information is important. Logging data in a JSON format gives you the ability to query logs using tools such as Google BigQuery, giving you another window into system behavior. This also gives you an opportunity to create metrics and alerts from log information. Schemas can be a great help to this end—a schema for log messages will keep your log format consistent across different teams and services. This makes analysis a lot simpler than having to accommodate different log format styles.

One of the pipelines I’ve worked on used logs as a cheap way to record and analyze profiling data, something you’ll see in Chapter 11, which covers monitoring. When execution of the profiled tasks finished, the results were written to the log in JSON. Our team could later query the logs to acquire and analyze the profiling data.

For example, you could capture the earlier debug messages in JSON to see which species were extracted for a given batch of bird survey data:

extract_info = {"user": user_id, "species": species}
logger.debug('Finished extracting species: %s', extract_info)

The preceding code would produce log messages like the following:

[DEBUG] Finished extracting species: {'user': 'user1', 'species': 'night heron'}
[DEBUG] Finished extracting species: {'user': 'user2', 
                                      'species': 'great blue heron'}
[DEBUG] Finished extracting species: {'user': 'user3', 'species': 
                                      'great blue heron'}

With the log data in JSON format, you can extract attributes:

SELECT 
    JSON_VALUE(log_data_json,'$.user) AS user, 
    JSON_VALUE(log_data_json,'$.species) AS species
    . . .

In the preceding code, log_data_json can be extracted from the log messages using REGEXP_EXTRACT to capture the data following "Finished extracting species:", and PARSE_JSON can be used to convert the log string to JSON.

Summary

Much like refocusing your diet on eating real food, logging in cloud data pipelines benefits from taking a step back from the constituent components and considering the picture on a larger scale.

In this chapter, you saw how logging practices designed without scalability in mind can negatively impact performance and cost, while in the worst cases can also hinder your ability to use logs for debug and analysis. Be judicious when logging data, and think about how many times a log message may be emitted when running at scale.

When it comes to reducing the costs of logging, setting retention periods and using filters in your cloud logging settings can reduce the amount of data you collect and store. On the code development side, splitting log messages into different levels keeps verbose debug information out of environments where it isn’t needed. For especially verbose modules, selectively enabling debug logging can give you more control.

You can minimize logging overhead in Python by leveraging the string interpolation provided by logging methods, rather than interpolating strings ahead of time. Setting up conditional logging will limit logs to circumstances where the additional information is helpful, such as if an exception occurs. This not only lowers log costs and performance impacts but tidies up your logs as well.

Finally, when code can be split across multiple processes, workers, and deployments, including identifying information in log messages is indispensable for identifying the data or processes that produced the message. For further introspection and analysis, logging diagnostic data in JSON format enables you to leverage tools for querying logs.

In this chapter, you saw how to cost-effectively use logging to leave clues for data pipeline debug and observability. The next chapter illustrates how to monitor data pipelines for debug, design, and cost efficiency. Oftentimes, monitoring lets you know a problem occurred, and logs provide more detail to help you root-cause the issue.