Site issues...

Starting on Friday June 12, 2009 we started to see general issues with performance degredation across the site. Since that time we have actually uncovered several issues that are contributing to poor performance:

• Database: Several queries were introduced last week that did not have proper indexing. Queries were also improperly balanced against the master/slave databases.
• Ingenio: One of our partners (Ingenio) appears to be experiencing some issues with site performance. I have tracked several occasions where the page load time has gone upwards of 50 seconds for periods of time lasting approximately 10 minutes.
• JavaBridge: Our old inverted index is still being phased out. We have witnessed that when the site becomes unstable due to issues with external sites (like Ingenio) or because of the database that some of the HTTP workers begin to hang and, in fact, rarely if ever recover. They are essentially dead processes.

Database

Throughout the weekend we have worked at correcting the issues with the database. We optimized the tables, put new indexes on, and rebalanced the queries. We have also ordered a new database slave to help offload some of the work. For the most part the database is now functioning ok even though there is still room for improvement.

Ingenio

We have informed Ingenio that we have been seeing several issues where their response times can vary from the normal 0-2 second range all the way to the 15 to 55 second range. Generally, these periods last around 5 to 10 minutes.

Below is a sampling from multiple time periods recorded in our error logs.

[Tue Jun 16 11:49:34 2009] [error] [client 209.96.211.53] PHP Warning: file_get_contents(http://api.ingenio.com/O1Lgyto6/GetListi

ngs.asmx/lq?a=O1Lgyto6&l=Norfolk%2C%20VA&dl=&i=0&n=25&tl=20&ip=209.96.211.53&lf=0&af=0&t=Cater

ers) [contents'>function.file-get-contents]: failed to open stream: HTTP request failed! in /disk2

/mojopages.com/htdocs/library/businessProfile.class.php on line 36, referer: http://www.bing.com/search?q=the+gourmet+gang%2C+norf

olk%2C+va&src=IE-SearchBox

[Tue Jun 16 12:11:20 2009] [error] [client 216.129.119.13] PHP Warning: file_get_contents(http://api.ingenio.com/O1Lgyto6/GetList

ings.asmx/lq?a=O1Lgyto6&l=San%20Diego%2C%20CA&dl=&i=0&n=25&tl=20&ip=216.129.119.13&lf=0&af=0&t

=Auto%20Repair%20%26%20Service) [contents'>function.file-get-contents]: failed to open stream: Conn

ection timed out in /disk2/mojopages.com/htdocs/library/businessProfile.class.php on line 36

[Tue Jun 16 13:50:44 2009] [error] [client 65.55.105.88] PHP Warning: file_get_contents(http://api.ingenio.com/O1Lgyto6/GetListin

gs.asmx/lq?a=O1Lgyto6&l=Poway%2C%20CA&dl=&i=0&n=25&tl=20&ip=65.55.105.88&lf=0&af=0&t=Funeral%2

0Planning%20Services) [contents'>function.file-get-contents]: failed to open stream: HTTP request f

ailed! in /disk2/mojopages.com/htdocs/library/businessProfile.class.php on line 36

[Tue Jun 16 14:49:10 2009] [error] [client 121.254.193.213] PHP Warning: file_get_contents(http://api.ingenio.com/O1Lgyto6/GetLis

tings.asmx/lq?a=O1Lgyto6&l=Houston%2C%20TX&dl=&i=0&n=25&tl=20&ip=121.254.193.213&lf=0&af=0&t=O

il%20Field%20Equipment) [contents'>function.file-get-contents]: failed to open stream: HTTP request

failed! in /disk2/mojopages.com/htdocs/library/businessProfile.class.php on line 36, referer: http://mojo.chron.com/

[Tue Jun 16 16:09:09 2009] [error] [client 66.249.71.80] PHP Warning: file_get_contents(http://api.ingenio.com/O1Lgyto6/GetListin

gs.asmx/lq?a=O1Lgyto6&l=Churchville%2C%20MD&dl=&i=0&n=25&tl=20&ip=66.249.71.80&lf=0&af=0&t=Fun

d%20Raising%20Organizations) [contents'>function.file-get-contents]: failed to open stream: HTTP re

quest failed! in /disk2/mojopages.com/htdocs/library/businessProfile.class.php on line 36

[Tue Jun 16 17:49:27 2009] [error] [client 209.202.168.74] PHP Warning: file_get_contents(http://api.ingenio.com/O1Lgyto6/GetList

ings.asmx/lq?a=O1Lgyto6&l=Washington%2C%20DC&dl=&i=0&n=25&tl=20&ip=209.202.168.74&lf=0&af=0&t=

Landscape%20Contractor) [contents'>function.file-get-contents]: failed to open stream: HTTP request

failed! in /disk2/mojopages.com/htdocs/library/businessProfile.class.php on line 36

Java Bridge

Perhaps most interesting of all is the effect that these issues seem to have on the system. When monitoring the Apache process with mod_status you have access to what is referred to as the "scoreboard".

The scoreboard represents the state of all the http connections (processes) that are going on in the system at any given moment. For example, when the system is performing normally the scoreboard looks like this:

Scoreboard Key:
"_" Waiting for Connection, "S" Starting up, "R" Reading Request,
"W" Sending Reply, "K" Keepalive (read), "D" DNS Lookup,
"C" Closing connection, "L" Logging, "G" Gracefully finishing,
"I" Idle cleanup of worker, "." Open slot with no current process

_CC_WWCK__C__CKWKWCCCC__KCWKCK_KCWW_WWCK._._...KW..K...CK.W..K..

.C._.C.WCCC._.C_......W...................._.K..................

................................................................

................................................................

................................................................

................................................................

................................................................

....................................................

However, when the system has had an issue (database lock or hangup with an advertising partner) we see the scoreboard look more like this:

WWWWKWWWCWWCKWWWCWWWWWCWKCWWWWWWWWWWWWWWWCKWWWWWWCWWKKCCWWCWWWWW

WWCRWWWWKWCWWWWWWWWWWCWWWWWWWKWWWKWKWWWWWWWWWWCWWWWWWWWWWWWWWCKW

WWWWWWKCWWWWWWWCWWCWWWWWWWWWWCWWWWWWWCWWWWCWWWWWWKWWWWWWWWWWWWWW

CWWWWWWWRWWCWWWWWWWWWWWWWWWWCWWWWCCCWWWWWWWKKWWWWWWWWWWWWWWWWWWW

WWWWCWWWWWWWWWWWWWCWWWWWWWWWCWWWWWWCKWWCWWWWWWWWWWWWWWWWWWWWWWWW

WWWWWKWWWWWWWWWWWWWWWWWCWWWWCWWWWWWWWWWWWWWWCCWWWWWWWWWWKCWWWWWW

WWWWCWWWWWWWWWWWWWWWWWWWWCWWWWWWKWWWWWWWWWWWWWWWWWWWWWWWCWWWWWWW

WWKWWWWWWWCWCWWWWWWWWWWWWWWWWWKWCWWKWWWWWWKWWWCKWWWW

This indicates that there are a substantially large number of processes "sending reply"... or are they???

In fact, it is possible to determine what the process is up to by doing an "strace -p " command which will show you the current system call as well as any other system calls a process is making. If you take one of the processes above stuck in the "W" state and run an strace you get back something like this:

poll([{fd=34, events=POLLIN|POLLERR|POLLHUP, revents=POLLIN}], 1, -1) = 1

This indicates that the process is actually waiting for to read from the file descriptor with id = 34. That's not too helpful unless you can figure out what file descriptor 34 actually is. That's what the "lsof" command is for. Running "lsof -p " you will actually get a list of the open files for a process. If I run this on the http process I can find that the file descriptor for fd=34 is actually a socket to the localhost on port 9267. Getting closer...

Now that you know the port that the http process is waiting on you can figure out what process actually has that port open by running another "lsof | grep 9267" and finding out which command has a bunch of those ports open with connections to http procs.

It turns out that the command that corresponds to the lsof is "java" and now you know that it's a java process holding things up. The answer...

So, after all of the above it's clear that the Java bridge (that we are transitioning away from in favor of Solr) is actually holding up the apache processes and preventing them from returning successfully. I am going to continue to dive into why the java process is hung by running a "jstack" on that java process to see what's going on. However, it is also somewhat moot because we will be transitioning off of Solr in the very near future.

Resolution:

There are three steps to resolve:

1. I'm going to continue to try to figure out what is hanging up the processes by running a jstack.
2. We should continue to transition away from the Java bridge quickly by moving to Solr which is much more stable and allows a much greater degree of debugging.
3. I have implemented an auto-restart script in the interim that will detect when we have reached over a certain number of http processes that are hung and will restart the http service if it fails to check three times in 5 second intervals.

#3 is a workaround that is not ideal because it means some connections are still getting hung and some will still get reset but it is better than the current situation where the hung processes are allowed to stick around and consume available system slots that could be used to process other requests.