Logs and Traces: Two Houses Unalike in Dignity
Tags: tracing, logging, aws, observability
Published: 2020-10-23 21:21:50

<span style="font-weight: 400;"><a href="https://www.imohealth.com/">Intelligent Medical Objects</a> (IMO) and its clinical interface terminology form the foundation healthcare enterprises need, including effective management of Electronic Health Record (EMR) problem lists and accurate documentation. Over 4,500 hospitals and 500,000 physicians use IMO products on a daily basis.</span>

<span style="font-weight: 400;">With Honeycomb, the engineering team at IMO was able to find hidden architectural issues that were previously obscured in their logs. By introducing tracing into their .NET application stack in AWS, they were able to generate new insights that unlocked reliability and efficiency gains.</span>

<span style="font-weight: 400;">Michael Ericksen, Sr. Staff Software Engineer at IMO, contributed this guest blog detailing the journey.</span>

<hr />

<span style="font-weight: 400;">At IMO, our 2019 engineering roadmap included moving application hosting from multiple data centers into AWS. The primary hosting pattern to migrate was a </span><span style="font-weight: 400;">.NET</span><span style="font-weight: 400;"> application running on a Windows instance behind a load balancer. In AWS, we use SSM documents written in PowerShell to define the steps to install agents, configure IIS, and perform other machine configuration prior to installing application code. We compose these discrete documents into orchestration documents (more than 25 in total) that execute upon instance launch based on the tags associated with the instance.</span>
<h2><b>Uncovering issues with trace instrumentation</b></h2>
<span style="font-weight: 400;">Our production applications have predictable load distribution during core business hours. We don’t see traffic spikes that demand instantaneous scaling. Development teams use scheduled Auto Scaling Group actions in our pre-production accounts to toggle capacity after business hours, generating significantly more activity. After a year of reliable operation under lower load parameters, we started hearing reports from internal users that the provisioning service in these pre-prod accounts was intermittently failing.</span>

<span style="font-weight: 400;">However, we didn’t have an easy toolset and vocabulary for describing our service reliability. We had logs! Unstructured ones. Lots of them.</span>

<em><a href="https://www.honeycomb.io/wp-content/uploads/2020/09/default-log-output-high-res-e1601333196170.png"><img class="size-full wp-image-7774" style="width: 100%; max-width: 750px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/default-log-output-high-res-e1601333196170.png" alt="Default log output generated during SSM provisioning" /></a> Default log output generated during SSM provisioning</em>

<span style="font-weight: 400;"> </span>
<span style="font-weight: 400;">Debugging issues for end-users meant searching through the copious logs generated by our processes. A dashboard aggregated the number of errors that appeared in the log files. That visibility helped us stabilize the service, but it didn’t provide critical insights to improve service operation for users.</span>

<span style="font-weight: 400;">I had used the </span><a href="https://github.com/honeycombio/agentless-integrations-for-aws/blob/main/terraform/cloudwatch-logs-json.tf"><span style="font-weight: 400;">Honeycomb agentless CloudWatch integration</span></a><span style="font-weight: 400;"> to ingest structured logs from Lambda functions. I was optimistic I could adopt a similar pattern to provide visibility into our provisioning process. The germ of the idea was simple:</span>
<ol>
 	<li style="font-weight: 400;"><span style="font-weight: 400;">Write structured logs to </span><span style="font-weight: 400;">stdout</span></li>
 	<li style="font-weight: 400;"><span style="font-weight: 400;">Ingest them via CloudWatch</span></li>
 	<li style="font-weight: 400;"><span style="font-weight: 400;">Forward them to Honeycomb using the agentless CloudWatch integration</span></li>
</ol>
<span style="font-weight: 400;">One key technical difference between a Lambda function and SSM documents is that functions hold context while dispatching the next operation. For SSM documents, we pushed in-process spans to a stack saved to the local file system. As spans completed, we popped them from the stack and wrote them as structured JSON logs to CloudWatch. Since our SSM documents execute sequentially, there are minimal concerns about concurrency.</span>

<span style="font-weight: 400;">For more technical implementation details, the source code for the initial version is on </span><a href="https://github.com/ericksoen/aws-systems-manager-observability-demo/blob/master/terraform/ec2_instance/functions.ps1"><span style="font-weight: 400;">GitHub</span></a><span style="font-weight: 400;">. </span>

<a href="https://www.honeycomb.io/wp-content/uploads/2020/09/simple-tracing-cloudwatch-stdout-high-res-v2.png"><img class="wp-image-7772 size-large" style="width: 100%; max-width: 750px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/simple-tracing-cloudwatch-stdout-high-res-v2-1024x154.png" alt="CloudWatch agent latency" /></a> <em>CloudWatch agent latency</em>

<span style="font-weight: 400;">The first time I saw the trace from this implementation I was certain there was an instrumentation bug: </span><i><span style="font-weight: 400;">Why would an SSM document composed of two steps that each write a single line to </span></i><i><span style="font-weight: 400;">stdout</span></i><i><span style="font-weight: 400;"> take more than 25 seconds to complete?!?</span></i>

<span style="font-weight: 400;">The provisioning execution time comprises a fractional percentage of the total execution time. That impact is magnified by the number of SSM documents (typically 15-25 documents) that execute during our primary provisioning processes. With trace instrumentation, that behavior was immediately visible.</span>

<a href="https://www.honeycomb.io/wp-content/uploads/2020/09/default-log-output-highlighted-high-res.png"><img class="size-full wp-image-7771" style="width: 100%; max-width: 750px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/default-log-output-highlighted-high-res.png" alt="Default log output with highlighting" /></a> <em>Default log output with highlighting</em>

<span style="font-weight: 400;"> </span>
<b>We’d overlooked past performance issues numerous times while debugging other problems because they were obscured by the log structure.</b><span style="font-weight: 400;"> Similarly, the log structure precluded the type of open-ended curiosity we associate with observability:</span>
<ul>
 	<li style="font-weight: 400;"><span style="font-weight: 400;">What provisioning steps execute the most frequently?</span></li>
 	<li style="font-weight: 400;"><span style="font-weight: 400;">What provisioning steps fail most frequently?</span></li>
 	<li style="font-weight: 400;"><span style="font-weight: 400;">Does introducing a new agent version preserve the stability of the system or does it de-stabilized it?</span></li>
</ul>
<h2><b>Debugging idle time in our provisioning service</b></h2>
<span style="font-weight: 400;">As we debugged potential causes of the issue (shoutout to Narendra from AWS technical support), one detail became clear: </span><b>we had two performance issues with a similar signature instead of the one we imagined</b><span style="font-weight: 400;">.</span>

<span style="font-weight: 400;">The first issue presented when writing logs to </span><span style="font-weight: 400;">stdout</span><span style="font-weight: 400;"> and sending them directly to CloudWatch. This was the eyebrow-raising performance issue detailed above.</span>

<span style="font-weight: 400;">However, our production provisioning service uses a different strategy to ingest logs into CloudWatch. For this second strategy, there was no detectable performance penalty. Yet all of our telemetry continued to show 10-20 second gaps of time between steps. We estimated three to five minutes of idle time during end-to-end execution. Curious.</span>

<a href="https://www.honeycomb.io/wp-content/uploads/2020/09/tracing-cloudwatch-agent-high-res-v2.png"><img class="size-full wp-image-7773" style="width: 100%; max-width: 750px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/tracing-cloudwatch-agent-high-res-v2.png" alt="IMO end-to-end provisioning" /></a> <em>IMO end-to-end provisioning</em>

<span style="font-weight: 400;"> </span>
<span style="font-weight: 400;">We slowly unveiled a </span><i><span style="font-weight: 400;">subtle</span></i><span style="font-weight: 400;"> issue in the PowerShell code that executes during our provisioning process. At various points, we use functions from </span><span style="font-weight: 400;">AWSPowerShell</span><span style="font-weight: 400;"> modules to retrieve configuration from a remote source, usually SSM Parameter Store. There’s a significant </span><a href="https://awsinsider.net/articles/2019/08/14/powershell-revamp.aspx"><span style="font-weight: 400;">performance penalty</span></a><span style="font-weight: 400;">  when first importing </span><span style="font-weight: 400;">AWSPowerShell</span><span style="font-weight: 400;"> modules into your PowerShell session.</span>

<span style="font-weight: 400;">We also learned our strategy for  module imports </span><i><span style="font-weight: 400;">“… are always applied globally, and must be met, before the script can execute.”</span></i><span style="font-weight: 400;"> The performance penalty for importing </span><span style="font-weight: 400;">AWSPowerShell</span><span style="font-weight: 400;"> modules occurs outside of </span><i><span style="font-weight: 400;">any</span></i><span style="font-weight: 400;"> application telemetry that attempts to measure it.</span>

<span style="font-weight: 400;">If you want to experiment with this behavior, we’ve included the steps to reproduce in our </span><a href="https://github.com/ericksoen/aws-systems-manager-observability-demo#performance-delay-due-to-awspowershell-modules"><span style="font-weight: 400;">GitHub project</span></a><span style="font-weight: 400;">.</span>
<h2><b>Watching code go live to fix the issue</b></h2>
<span style="font-weight: 400;">After identifying our implementation of </span><span style="font-weight: 400;">AWSPowerShell</span><span style="font-weight: 400;"> as the root of our performance issues, we evaluated an array of resolution options. Caching modules across PowerShell sessions wasn’t technically feasible. Restructuring provisioning documents to execute within a single PowerShell session was a significant time commitment. Rewriting our provisioning service to use </span><a href="https://aws.amazon.com/about-aws/whats-new/2019/12/introducing-ec2-image-builder/"><span style="font-weight: 400;">AWS Image Builder</span></a><span style="font-weight: 400;"> was the long-term direction we agreed was most appropriate. However, rewrites never happen overnight and change frequently introduces new failures.</span>

<span style="font-weight: 400;">In the interim, we added a new step to install the AWS CLI and modified function calls to </span><i><span style="font-weight: 400;">prefer</span></i><span style="font-weight: 400;"> using the AWS CLI,before falling back to using </span><span style="font-weight: 400;">AWSPowerShell</span><span style="font-weight: 400;"> modules if it wasn’t available.</span>

<span style="font-weight: 400;">Initially, we deployed the change to our lowest application environment and compared the performance delta.</span>

<a href="https://www.honeycomb.io/wp-content/uploads/2020/09/romeo-and-juliet.gif"><img class="aligncenter wp-image-7776 size-full" style="width: 100%; max-width: 500px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/romeo-and-juliet-e1601412814521.gif" alt="A young Leonardo DiCaprio in Romeo and Juliet says “But, soft! What light through yonder window breaks?”" width="500" height="200" /></a> <em>A young Leonardo DiCaprio in Romeo and Juliet says “But, soft! What light through yonder window breaks?”</em>

<span style="font-weight: 400;"> </span>
<span style="font-weight: 400;">One of our key performance metrics is time from instance launch until application code begins installation. Our logs made this difficult to calculate for a single instance and impossible to measure at scale. Our trace data, however, made this simple: </span><i><span style="font-weight: 400;">measure what matters to your users</span></i><span style="font-weight: 400;">.</span>

<a href="https://www.honeycomb.io/wp-content/uploads/2020/09/performance-improvement-high-res.png"><img class="size-full wp-image-7775" style="width: 100%; max-width: 750px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/performance-improvement-high-res.png" alt="Graph showing performance improvement between account with CLI change and account without" /></a> <em>Graph showing performance improvement between account with CLI change and account without</em>

<span style="font-weight: 400;"> </span>
<span style="font-weight: 400;">The graphs show a significant performance increase when using the AWS CLI. At the 50th percentile, we improved performance by more than 2 minutes and improved performance by more than 4 minutes at the 99th percentile. In fact, the 99th percentile performance metrics when using the AWS CLI was almost as fast as the 50th percentile times when it was not. ¡Que bueno!</span>
<h2><b>Conclusion</b></h2>
<b>Building observability into the foundation of systems can dramatically reveal potential architectural issues long before it reaches customers.</b><span style="font-weight: 400;"> Even experienced peer reviewers frequently cannot predict the way multiple complex systems converge and intersect to magnify performance issues: </span><b>we were paying performance penalties once per document, not once per end-to-end execution</b><span style="font-weight: 400;">.</span>

<span style="font-weight: 400;">Although this issue could have been discoverable in our logs, it remained opaque to us for more than a year until our tracing revealed it. The trace data we generate also provides new insights into how to operate our system more reliably and efficiently.</span>

<a href="https://www.honeycomb.io/wp-content/uploads/2020/09/aggregate-performance-high-res.png"><img class="size-full wp-image-7770" style="width: 100%; max-width: 750px;" src="https://www.honeycomb.io/wp-content/uploads/2020/09/aggregate-performance-high-res.png" alt="Graph showing execution count and duration percentiles for provisioning steps." /></a> <em>Graph showing execution count and duration percentiles for provisioning steps.</em>

<span style="font-weight: 400;"> </span>
<span style="font-weight: 400;">As seen in the above graph, there’s a significant decline in execution time after our four longest run steps. Moreover, one of those longest running steps executes far less frequently than its peers.</span>

<span style="font-weight: 400;">If we were to only solve the time-gap fix discussed above and then optimize the three most frequently executed, longest running steps, we could improve performance for one of our key user metrics by more than 9 minutes, or 62% of the total execution.</span>

<span style="font-weight: 400;">As Cindy Sridharan notes in her report on </span><a href="https://www.oreilly.com/library/view/distributed-systems-observability/9781492033431/"><span style="font-weight: 400;">Distributed System Observability</span></a><span style="font-weight: 400;">:</span>
<blockquote><span style="font-weight: 400;">The goal … is not to collect logs, metrics, or traces. It is to build a culture of engineering based on facts and feedback, and then spread that culture within the broader organization</span></blockquote>
<span style="font-weight: 400;">With remarkable economy of language, another familiar CTO expressed her sentiments even more succinctly: </span><a href="https://twitter.com/krisnova/status/1002508776447102976?s=20"><span style="font-weight: 400;">“I’m so done with logs.”</span></a><span style="font-weight: 400;"> We’re so done with logs too, Charity.</span>

Join the swarm. Get started with [Honeycomb for free] (https://ui.honeycomb.io/signup?&utm_source=Devto&utm_Devto=blog&utm_campaign=referral&utm_keyword=%7Bkeyword%7D&utm_content=logs-and-traces-two-houses-unalike-in-dignity/).