I've been maintaining an application for the last 6 years. During those 6 years, we noticed what we came to call "the bad problem".

This application stores its sessions in a postgres database(so that we can load balance the web servers, and not use sticky sessions). During the busy season, we would notice db backends building up. Eventually, they could build up to the point where memory on the db server was exhausted, and new connections would be rejected. This was bad. For the longest time we couldn't find the source of our problem. We theorized it had to do with session locking, and we spent a lot of time building tools to track down how it happened.

short summary of tools created to debug:
startProfile('smarty','display');endProfile('smarty','display');
tracksession.php(a tool to show all the requests by a certain sessionId from the profile log)
set statement_timeout

Short summary of problem:
When a browser loses its internet connection unexpectedly, Apache can't tell that the connection is dead, so waits as long as its Timeout directive for a packet to be received from the client. This means that in PHP, an echo() call can hang as long as 120 seconds by default on newer apache installations. Any time your application will send data to the client, you should/must call session_write_close to avoid locking the session for the length of Apache's Timeout directive.

Long description of tools for tracking the problem:
startProfile('smarty','display');endProfile('smarty','display');
startProfile and endProfile are functions for logging performance of requests. By using the define('logprofile', 'print'); in your etc file, you can see what the measurements are, which is useful in development. define('logprofile', '/home/apps/log/profile'); will log the performance to a file(actually two files in the directory, profile.log and longest.log). Zoop already log's the total request time, and the time taken in sql queries, as well as the number of sql queries and the longest sql query. By adding startProfile('myapp', 'myfunc'); at the beginning of a function and endProfile('myapp','myfunc'); at the end, you can add profiling of your own functions. The first param, 'myapp' is the grouping used. All the calls to startProfile('myapp') will be grouped together and reported as a total time in the log. It will also log which 'myfunc' was the longest. A line from the profile.log can look like this:

"01/26/09 02:49:59.0779", "@ROOT/keepOpen/get", "1", "0.018956899642944", "0.0052809715270996", "query_497d24d71c653", "/home/apps/code/myapp/index.php @ line 51", "0.0052809715270996", "session", "1", "0.0051000118255615", "0.0051000118255615", "session_connect", "/home/apps/code/myapp/index.php @ line 51", "https://example.com/myapp/index.php/keepOpen", "3c928e7093a0da3ef8e91409a05fdf61"

First is the time the request started in UTC. Then the name of each zone in the request followed by the page in the request, then the method(get or post). zone_default is known as @ROOT. then it displays the number of sql queries, the total time of the request, the time spent in seql queries, a code to look up the longest query in longest.log, the location the longest query was called from, and the length of the longest query. Then it begins to list the other groupings you have specified. In this case the request called startProfile('session', 'session_connect');endProfile('session','session_connect'); and that was all. The first item after "session" is the number of calls in the "session" group, the total time, the longest call, the name of the longest call, the location of the longest call, then the url of the request and the session_id.

My favorite tool we created is tracksession.php. It uses the profile.log to see exactly what requests were made during a session from start to finish, and then we can diagnose any performance problems the user may see. It greps the profile.log file for a string that you give it, returning the rows that match. It's quite simple, but very helpful. It can be used to either track a session, or simply to see all the requests that are similar, or were made in the same minute.

Timeout values were masking our problem in a couple ways. PHP has "max_execution_time" that is set by default to 30 seconds in the php.ini. Obviously our requests were taking much longer than that. From a note at http://us2.php.net/set-time_limit

Note: The set_time_limit() function and the configuration directive max_execution_time only affect the execution time of the script itself. Any time spent on activity that happens outside the execution of the script such as system calls using system(), stream operations, database queries, etc. is not included when determining the maximum time that the script has been running.

So our database calls were not being terminated after 30 seconds, but waiting indefinitely for the lock. And the original request that hung was not being terminated after 30 seconds, but waiting for apache to timeout the connection. Using sql_query("SET statement_timeout 1000");, we are able to control at least the script waiting for the lock. It will now wait for a second at a time. If you then allow the query to be retried 10 times, you can give a script 10 seconds to get the lock, then trigger_error and terminate the script, minimizing the buildup of db processes.

I'll be committing some of these tools to zoop. I hope you enjoy them!