Instance Thrashing with Amazon EC2 Autoscaling

This post explains a situation our team encountered when we tried to use ec2 auto scaling, for a particular application. We didn't ended up using auto scaling. Instead, we allocated enough instances in advance to respond to anticipated load.

In a nutshell: Automatically added instances could not handle the high load, and were immediately removed from the pool, rendering auto scaling unusable.

The graph depicts CPU utilization for 30 ec2 large instances.
We started with 4 instances, allowing the group to grow to up to 30 instances. The load test was designed to gradually increase the load to the maximum expected, and then sustaining it at that level for a period of time.
The 4 instances behaved as expected, until the point where we experienced request timeouts. New instances were added to the group as expected, but we didn't observe an improvement in response time, or a reduction in dropped requests. This continued until the load was eventually reduced.
During the high load period, we kept querying for the number of healthy instances, and always found the number too low. The average was about 7.
It's not immediately apparent in the graph above, but it does show instances coming into the pool, at which point their CPU utilization peeks, then soon after, the same instances' CPU utilization going down.
We expected that with new instances added to the pool, that CPU utilization will be reduced across all instances. Since all instances are configured the same way, we expected more or less the same CPU utilization across the group. Also, we expected the response time to go down in a similar pattern.
The average response time stuck at 60 seconds, which is a signal that instances are dropping requests. The request timeout was set at 60 seconds, thus skewing the average to this number.
This behavior led us to conclude that our instances could not start up normally under a heavy load. Further investigation was certainly due, but we never got around to it. It was deemed safer to keep enough instances up to respond to the anticipated load, which we confirmed in a subsequent load test.

A Story of a Software Project

Iteration 1: The team picks up the first stories, and makes good progress. The result is showcased to the customers. The mood is encouraging.
Iteration 2: The team churns a bit, trying to get the first stories closed and iron out some technology choices.
Iteration 3: Not enough stories are being closed. The team's velocity is lower than needed. The PM gets worried, and starts calling meetings and raising red flags. The PM declares that the team needs to catch up, and look for ways to increase velocity.
Iteration 4: The team makes good strides, and appears to be back on track. Nerves settle down a bit.
Iteration 5: The team's velocity is soaring. The PM says that given the current velocity, the team will meet its target date. The team starts taking care of technical debt.
Iteration 6: The business functionality is taking shape. The customers start to get a feel of how the system works. They start asking for modifications.
Iteration 7: The customers become more demanding. They notice some gaps between the functionality of the application, and what is needed to run the business. Defects start to creep in.
Iteration 8: The PM talks the business out of some of their demands, and the team devises workarounds for some outstanding issues.
Iteration 9: Faced with approaching deadlines, the PM asks developers to stay late and work over the weekends to finish the remaining tasks. The code quality suffers and technical debt increases.
Iteration 10: The team manages to finish all the remaining tasks. The application is put in production, with minor hiccups. Time to celebrate.


Does this sound familiar?
The team delivered on time. Is there a problem here?
The above pattern causes hardship for the team. The resulting code quality is rarely satisfactory. But we shouldn't be surprised or get overly worked out because of things that are really to be expected:
- Estimates are not always met, because they are estimates.
- The team takes more time in the first iterations because it's the first time this team tackles this problem.
- The customers don't like what they see the first time, because it's the first time they see it.
- The project is taking more time than expected because our expectations are just now being reality checked.
- The developers are being asked to work extra time because the team's management over-promised. However, the developers had no clue initially whether these promises can be met. Everything looked good on paper.

What's the way out of this?
This is not an easy problem. What makes it even more difficult is the fact that the team delivered after all, reducing the incentive for change. There are ways, however, to make things better:
- Educate all parties on all aspects of the project.
- Get the customers involved as early as possible.
- Manage all parties' expectations.
- Communicate regularly, and facilitate information sharing.
- Make it clear that the process of adaptation also includes dates and scope.
- Learn from the past. If you've seen this before, it's likely that you'll see it again unless you change your approach.

Shouldn't We Local-Optimize at Bottlenecks?

The short answer is no. Once we start thinking local, we are heading down the wrong path.

Consider what we should do at a bottleneck:

• Increase the resource's throughput, by increasing its efficiencies.
• Manage the flow in the system to reduce idle time at the resource.
• Add more capacity, by introducing other resources capable of the same function.
• Outsource a portion of the work to resources outside the system.
• Rethink the need for some work to go through the bottleneck.

You'd notice that only the first of these points is local in nature, and we should only consider it as an option. It may not be the best one.

What is Wrong with Local Optimization Anyway?

How could it be wrong to optimize anything, local or not?
Well, if by local optimization we mean having a resource in our system utilize an optimum amount of its inputs, to produce timely, sufficient, but not excessive, output to subsequent steps in the process, then there is nothing wrong, as long as this optimization contributes positively to the system's goal.
Note that timely, sufficient, and not excessive, output is defined by subsequent steps in the process. As such, this output might, at times, be zero.
Note also that optimizing the whole system may call for one step or process to be removed altogether.
If this is how we are approaching the problem of efficiency, then we are not actually doing local optimization.

Consider, however, the following approaches to optimization:

• Increasing the resource utilization to 100%.
• Getting the maximum possible throughput out of every resource.
• Keeping everyone busy all the time.
• Removing all idle time.

If this is our focus, then we are heading for trouble, and we are introducing a significant waste in our system.

To see why this is the case, consider the following consequences of increasing a resource's throughput in our system to the maximum:

• More inventory to manage in subsequent processes, If these subsequent processes are not ready, or capable, of consuming all the output.
• More load on subsequent processes, since now they will have more input to process.
• Delays in getting urgent work done, since there is no slack in the system to handle occasional spikes, resulting from natural statistical variations.
• More work being stuck at bottlenecks.
• Increasing demand artificially on up-stream processes, since this demand is not driven by the needs of the market or the ultimate customers.
• Increasing demand on resources required to maintain the high efficiency.
• The process of optimization itself will consume resources. The overall gain may not exceed the cost.

Local efficiency, then, is a waste. One has to look for alignment with the system's goals to define what, where, how, and how much to optimize, weighing costs against benefits.

"But wait," you may remark, "how about local optimization at bottlenecks?", which is, granted, a nice try. But this will have to wait for another post.

Does Waterfall Make More Sense?

I came in contact with a few people who were actually content with waterfall.
A senior dev explained to me that waterfall is simple, everyone gets it, and it's easy to implement. There are well defined, easy, consecutive steps to be followed.
An upper manger was very keen to find ways to convince his company's leadership that waterfall fits his department really well, thus avoiding the drive to adopt agile. From his perspective, waterfall provided predictability. He new at the beginning of the year what his budget is, what projects he will be working on, and what the duration of each projects will be.

It also makes sense to design something before building it. If you don't design it before hand, how do you know what you will be building? How do you know how much it will cost? How do you decide if it's worth it? How do you compare it to other options?

In our day-to-day life, we demand predictability. Before we offer a job to a carpenter to install new kitchen cabinets, or ask a mechanic to service our car, for example, we want to know before hand how much it will cost, and how long it will take. We are really disturbed when either of these estimates are not met, although we know they are just estimates.

So what is the problem in expecting the same from software projects?
We can always give the example of an apparently simple job gone badly, as when an air conditioning engineer starts asking you when was the last time you cleaned your air vents, or changed the air filters, only to discover that you'd have to pay more and wait longer to have your air system fixed. Let's put this example aside for now.
Instead, consider the how likely is the change in your project, from inception to project end, in the following areas:

• The business needs from your application.
• The specified requirements from your application.
• Your understanding of the requirements.
• Technology.
• The project team's mastery of the technology.
• The people who are doing the work.

If your meter reads anything other than low for all the above, you should rethink waterfall.
Because waterfall makes sense for certain types of projects. Software development projects are a breed of their own, with a lot of sub-varieties within.
And change is inevitable in software projects, because you'll never build the same application twice, for the same business need, with the same people, who have the same experience, using the same technology, will you?

Thin Slice vs. Layer-wise, Or Depth-first vs. Width first

Agilists always advocate for incrementally developing a thin slice of the application, in the form of a user story, that implements end-to-end changes that are required to deliver business value to the customer. This will normally entail changes to the UI, front-end logic, back-end components, databases, service interfaces, etc. This process results in the end user receiving value for every story delivered. The customer gets this value early, while developers have to manage only one small change at a time, and significantly reducing code integration overhead.
But what about efficiency?
Some will argue that working on different layers requires different skills, and that there is a waste incurred in task switching, e.g., switching from working on the UI to working on the back end. It can be demonstrated that working width-first, as in developing 10 UI components (A1, A2, A3, ...), , then 10 back end components (B1, B2, B3, ...), etc., will require less time than working depth-first (A1, B1, ...), then (A2, B2, ...).
But then, who's right?
In fact, both are. It is indeed more efficient to work on the same task type, since there is less task switching, and there are mass production techniques that could be employed. However, the customer gets value much later, process feedback is delayed, and there are more integration work and problems that are only discovered late in the process.
It so happens that in software development, the Agile method is far more superior. The benefits of an Agile process increase in line with the rate of change in the process.
But what about efficiency?
To the non-agilists, it should be noted that efficiency isn't the point. Thinking mainly about efficiency distracts from the goal of delivering more value to the customer, at a faster pace. To concentrate on efficiently producing UI components, for example, increases waste by delivering more than the customer needs, by increasing the rework required to adapt to changing/better understood customer needs, by delaying feedback, and by increasing work in progress. This is a form of local optimization that negatively impacts the overall goal.
But also, to the agilists, the efficiency argument should be understood. There will be opportunities during development to queue up similar tasks, and leverage specialized skills, and mass production techniques, to gain immediate task efficiency.
The idea, then, is to never let efficiency distract you from your gaol, and to only pursue it if it doesn't increase work-in-process, and doesn't delay feedback or customer value.

WebSphere Trace, Spring, commons ToStringBuilder, Hibernate, and LazyInitializationException

We've seen the exception below, because WebSphere diagnostics and tracing was enabled.
We disabled it by editing the logging properties from WebSphere console/Logs and Trace/select your server's/select Diagnostics Trace Server/Runtime/click Change Log Detail Levels, then editing logging information, and removing unneeded packages after "*=info:" ...

Stack trace:

[2009-07-23 15:56:10,078] WebContainer : 1651 org.hibernate.LazyInitializationException ERROR - could not initialize proxy - no Session
org.hibernate.LazyInitializationException: could not initialize proxy - no Session
at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:86)
at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:140)
at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:190)
at com.mycompany.myproject.domain.MyObject_$$_javassist_20.hashCode(MyObject_$$_javassist_20.java)
at org.apache.commons.lang.builder.HashCodeBuilder.append(HashCodeBuilder.java:452)
at org.apache.commons.lang.builder.HashCodeBuilder.reflectionAppend(HashCodeBuilder.java:413)
at org.apache.commons.lang.builder.HashCodeBuilder.reflectionHashCode(HashCodeBuilder.java:379)
at org.apache.commons.lang.builder.HashCodeBuilder.reflectionHashCode(HashCodeBuilder.java:155)
at com.mycompany.myproject.domain.DomainObject.hashCode(DomainObject.java:14)
at java.util.HashMap.hash(HashMap.java:324)
at java.util.HashMap.containsKey(HashMap.java:470)
at java.util.HashSet.contains(HashSet.java:207)
at org.apache.commons.lang.builder.ReflectionToStringBuilder.isRegistered(ReflectionToStringBuilder.java:135)
at org.apache.commons.lang.builder.ReflectionToStringBuilder.appendFieldsIn(ReflectionToStringBuilder.java:660)
at org.apache.commons.lang.builder.ReflectionToStringBuilder.toString(ReflectionToStringBuilder.java:867)
at org.apache.commons.lang.builder.ReflectionToStringBuilder.toString(ReflectionToStringBuilder.java:339)
at org.apache.commons.lang.builder.ReflectionToStringBuilder.toString(ReflectionToStringBuilder.java:173)
at org.apache.commons.lang.builder.ToStringBuilder.reflectionToString(ToStringBuilder.java:124)
at com.mycompany.myproject.domain.DomainObject.toString(DomainObject.java:24)
at java.lang.String.valueOf(String.java:1505)
at java.util.AbstractCollection.toString(AbstractCollection.java:469)
at com.ibm.ws.webcontainer.srt.SRTServletRequest.setAttribute(SRTServletRequest.java:488)
at org.springframework.web.servlet.view.AbstractView.exposeModelAsRequestAttributes(AbstractView.java:337)
at org.springframework.web.servlet.view.InternalResourceView.renderMergedOutputModel(InternalResourceView.java:206)
at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:257)
at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1183)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:902)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:807)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:763)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1095)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1036)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:118)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain._doFilter(WebAppFilterChain.java:87)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:832)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:679)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:565)
at com.ibm.ws.wswebcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:478)
at com.ibm.ws.webcontainer.webapp.WebAppRequestDispatcher.forward(WebAppRequestDispatcher.java:321)
at org.springframework.web.servlet.view.InternalResourceView.renderMergedOutputModel(InternalResourceView.java:236)
at org.springframework.web.servlet.view.AbstractView.render(AbstractView.java:257)
at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1183)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:902)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:807)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:571)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:763)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1095)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1036)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:145)
at com.opensymphony.module.sitemesh.filter.PageFilter.parsePage(PageFilter.java:119)
at com.opensymphony.module.sitemesh.filter.PageFilter.doFilter(PageFilter.java:55)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:186)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:130)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain._doFilter(WebAppFilterChain.java:87)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:832)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:679)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:565)
at com.ibm.ws.wswebcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:478)
at com.ibm.ws.webcontainer.servlet.CacheServletWrapper.handleRequest(CacheServletWrapper.java:90)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:748)
at com.ibm.ws.wswebcontainer.WebContainer.handleRequest(WebContainer.java:1461)
at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:118)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:458)
at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewInformation(HttpInboundLink.java:387)
at com.ibm.ws.http.channel.inbound.impl.HttpICLReadCallback.complete(HttpICLReadCallback.java:102)
at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:165)
at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)
at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)
at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:136)
at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:195)
at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:743)
at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:873)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1473)

Analysis

It seems that enabling logging for the package com.ibm.ws.webcontainer causes WebSphere to log request attributes. During view rendering, the call to request.setAttribute(), in Spring's AbstractView.exposeModelAsRequestAttributes() , which is implemented by com.ibm.ws.webcontainer.srt.SRTServletRequest.setAttribute(), attempts to log model attributes by calling toString(). We add our domain objects as values for model attributes, and our DomainObject implements toString() using Apache commons ToStringBuilder, which recursively walks the whole object graph, causing all references to be initialized. This all happens outside the boundaries of a transaction, and hence we get the exception above for our lazily loaded references.

Now this should be searchable, just in case ...