Demo: Tracing a Ruby web server


This article shows a demo of the kind of analysis that can be done using kernel tracing. Using only events coming from the Linux kernel, we can see how user applications behave, and how they interact with each other and with the rest of the system. The traces have been gathered using LTTng and the viewing is done in Trace Compass. The top view is the Control Flow View and it shows the state of all processes through time. The middle view is the actual trace, as recorded by LTTng. Events from this trace are used to generate all other views. Finally, the bottom view is the Critical Path View, created by Francis Giraldeau, and shows the critical path of a process.


This demo shows a Ruby server receiving requests from an outside source. Each request yields the creation of a new Ruby process to fulfill it. The top view shows that processes with PIDs 3177, 3211, 3244, etc. follow this pattern. It also shows that the process 3177 took more time than others to send the response.
The Critical Path View later shows all the other tasks that are on the critical path of the request, ie all tasks that interacted with the Ruby process, either voluntarily or not. The view shows that the Ruby process spent most of its time waiting for the swapper task, which is the idle task on Linux. Looking at the actual trace around the time when the Ruby process is awaken, we see that it was waiting on IRQ 30, which is, on this system, the network interface. Looking at the code of the application, we see that the first step is to fetch data from Amazon S3, which explains the wait for the network. This service could be optimized either by changing the data pipeline in the application (start processing AWS data as it comes in), by reducing the amound of data to be transfered, or simply by verifying that AWS SLA are met.
Note that there is a lot more to this trace to look at. There are many other tasks that the Ruby servers interacts with, and many other resources it's waiting on. Multiple potential optimizations can be inferred from this analysis.