Sunday, June 10, 2012

How we analyze the performance of large systems

Here at BackType, we're passionate about finding simple solutions to hard problems. We don't write perfect code, but we do aim to design systems in fundamentally flexible and scalable ways ? making smart design decisions often leads to unexpected benefits later on. This doesn't mean we don't embrace technical debt. We engineer systems with the intention to deliver product iterations as quickly as possible.

Our products and services handle close to a billion monthly requests; our approach to engineering frequently requires us to revisit systems to improve performance. It follows that measuring and understanding system performance is critical to us. There are lots of tools that can help, but often what we really need is something simple and extensible to identify bottlenecks or design flaws as quickly as possible. We decided to create our own system with the help of some open source software.

The key parts of the system are twofold: first, we expose an event timing library to all our applications. The second, and more interesting part of the system, is how we aggregate and analyze these measurements.

Timing Information

In our code we create a "timer" at runtime. Timers are really just a map of events to timing information. We then lace our code with "tokens". Each token is given a list of event names. Tokens are started and stopped throughout the code, with the final results being saved in the timer. At the end of execution we write the events and timing information to a Scribe server with a category (e.g. the name of the API/service), the current timestamp and a status key (e.g. an HTTP response code like 200 or 404).

Measurement & Analysis

Scribe allows us to aggregate log data in real time from our dozens of machines and many different services. Then we use a script to organize the Scribe logs in a way that we can work with. This organizer script runs on a cron and takes the raw Scribe logs, which have the above data JSON encoded, and appends the events to a file based on category, date and key. For example, all the responses to our Twitter link search API for the first hour of today that returned with an HTTP 200 would be located in /vol/perf/backtweets/2010/5/3/1/200.

Once we have organized all the events we use a simple command line tool for querying the data. The tool outputs key statistics and the distribution of the performance by time for each event we're logging (one service is usually made up of several events). This helps us identify which code paths, individual functions, or database calls are affecting performance.

Below is an example from a performance issue I debugged in our connect-stats method. This API returns a complete picture of social engagement for any URL, including the number of comments on the page, the number of tweets to the URL, the number of digg comments, the number of friendfeed comments, etc. The actual implementation has to hit few different indexes to build the full response, so it was unclear initially what was causing the issue.

$ python perf_log_distributions.py� /vol/perf/api_connect_stats/2010/3/29 req: ��� 1:��� ��������� 0��� ����������� 0.000000% ��� 5:��� ��������� 1��� ����������� 0.000960% ��� 10:��� �������� 216��� ��������� 0.207288% ��� 50:��� �������� 1421��� �������� 1.363684% ��� 100:��� ������� 31565��� ������� 30.291834% ��� 200:��� ������� 46989��� ������� 45.093711% ��� 500:��� ������� 18857��� ������� 18.096408% ��� 1000:��� ������ 2625��� �������� 2.519121% ��� 2500:��� ������ 1600��� �������� 1.535464% ��� 5000:��� ������ 875��� ��������� 0.839707% ��� 10000:��������� 52��� ���������� 0.049903% ��� 30000:��������� 2��� ����������� 0.001919% ��� >30000:�������� 0��� ����������� 0.000000%

1. Full timing for a sample of all requests to Connect-Stats


This script outputs the breakdown of timings for each event logged as part of a connect-stats request. For simplicity I only pasted the breakdown for "req", the timing of the full API call. Approximately 78% of requests were taking under 500ms to complete. So why were 22% so slow? Why were almost 1% of requests taking over 2.5 seconds? We created a query system that lets us eval simple expressions, perform ranged timestamp queries and filter the key using a regular expression. I then filtered my query on just the slow requests where the "req" event (timing the full API call) took more than 500ms to run:

$ python perf_log_distributions.py -q "[req]>500" /vol/perf/api_connect_stats/2010/3/29 tweetcount: ��� 1:������������ 0���������������� 0.000000% ��� 5:������������ 0���������������� 0.000000% ��� 10:����������� 23��������������� 0.447471% ��� 50:����������� 1133������������� 22.042802% ��� 100:���������� 337�������������� 6.556420% ��� 200:���������� 194�������������� 3.774319% ��� 500:���������� 768�������������� 14.941634% ��� 1000:��������� 1512������������� 29.416342% ��� 2500:��������� 896�������������� 17.431907% ��� 5000:��������� 261�������������� 5.077821% ��� 10000:�������� 15��������������� 0.291829% ��� 30000:�������� 1���������������� 0.019455% ��� >30000:������� 0���������������� 0.000000%

2. Timing of the "tweetcount" part of slow requests to Connect-Stats

Here I'm only showing the breakdown for the "tweetcount" part of the request (scanning all tags showed this one to be the culprit). For whatever reason retrieving the tweetcounts was sometimes slow (note this is the distribution only during slow requests).

Conclusion

Getting this system off the ground was easy ? just a matter of setting up Scribe and writing a few tools for timing, organizing the logs, and parsing/analyzing them. These tools don't solve every performance issue we run into, but they allow us to take on technical debt, and then quickly understand how to refactor and improve the systems that need to be scaled.

Permalink | Leave a comment  »

Source: http://tech.backtype.com/analyzing-the-performance-of-large-systems

computer repair overland park ks computer repair overland park yelp computer repair overland park ks computer repair overland park kansas

0 Comments:

Post a Comment

Subscribe to Post Comments [Atom]

<< Home