We're not at all sure it's db-related; we're trying to track down as many avenues as possible.

Here's a scatterplot of request completion time in microseconds as measured by httpd against client IP address, on a logarithmic scale.  Pretty much across the entire network topology, we're seeing some pretty horrible outliers on certain document pages, as well as main-page loads.

Blue == successful HTTP 200 return codes

Green == 401 Authorization required

Violet == client errors

Red == server errors

Greys == Not Modified

Our interpretation of this is as follows:

1) Our performance issues are not network-topology based.  Outliers are spread pretty much across the board

2) We're not seeing good caching behavior; we're looking at addressing this via mod_expires and moving static content to our proxy layer

Load and cpu utilization on the mysql machine is incredibly light, and we're not near our db connection pool limit.

The only slightly noteworthy thing is that cpu utilization on our jboss server jumped a bit after upgrading to 2.5.6 from 1.10.5:

Memory on the app servers seems fine:

Threads look ok:

Anything jumping out at you?  We have *got* to get the outliers down from where're they're at to come close to our internal SLA.

Is there any other profiling data we can provide?  Timing the thread-dumps to occur during the outliers is going to be non-trivial.

Given the following data on poorly performing urls, what would you tend to tackle if not the caches?

1) I've witnessed it, on the order of seeing the main page request for a small to medium-sized document take ~30s to complete.  Haven't see the 190s+ ones personally, though.

2) Inside the corporate firewall, w/ a 1gb network connection and very low latency, here's what I'm seeing in firebug:

3) This is not running on a VM.  It's running on 2 dedicated jboss app nodes... 8gb ram each, and I think 4 cores each.  These are *not* slow machines, nor are they suffering from any other load.

4) Haven't broken it down to know if we're talking specific documents or not yet, but given the number of problem documents, I think it's unlikely; there are about 287 unique documents showing performance outside of our SLA target.

• Can't easily hit just the app server; only an AJP connector is exposed, and that is only for the proxies.
• We're working on gathering data to tell whether the request rendering is a function of a specific ID or no.  But given that 287 is ~50% of our documents (afaik), I'd wager a beer on it being not ID-specific.
• We've replicated some of the long-running requests, and are attaching thread dumps.  For each general case, 10 dumps were taken on each of the two cluster nodes, staggered 5 seconds apart.  The cases were:
  

• We do have one customization; we've implemented an auth plugin to accept REMOTE_USER (coming from httpd+mod_auth_kerb) and, if needed, importing user information from LDAP to create users within clearspace.  This is to avoid forcing internal users to register, etc.

It's a Sun JDK, the dumps were generated through the jmx-console and run through links -dump.

20s to load a page *is* really bad   And that's not even the worst of it.

We've not seen anything on cpu utilization or load that disagrees w/ the monthly graphs posted above.  The box just seems to be sitting there

Performance doesn't appear to be very different w/ just one node vs two.  For a long time, we were running just one node, and performance seemed to be just as bad (we don't have the same degree of data from that timeperiod though).

It grew organically.  We did migrate from one db server to another, however.  I believe import/export was a typical mysqldump operation.

I'm not certain, I'll ask our DBA's.

We've very reluctant to do this; it would take a good deal of work to appropriately scrub the data, and doing so may taint its usefulness for you.  If absolutely necessary, we can discuss this further w/ Rajeev and our account rep on your side.

It does not appear to be directly related to single vs multi-node, based upon our logged data.

I think I mentioned this earlier in the thread, apologies if not... we have a custom AuthFilter that utilizes REMOTE_USER (coming from mod_auth_kerb) plus LDAP to instantiate user objects.  We pretty much followed your developer docs on the subject.  Aside from that, our only customizations are the fact that we package via RPM and deploy using puppet.

I'll include this in my request to the DBAs... when I hear back from them, I'll post more info.

Have you been able to make any headway understanding the cache effectiveness data I posted, or coming up w/ some recommended changes there?  I'm looking to do a point release in the next week or so, so I really need to pull the trigger on any changes there.

Here are the ten longest-running queries (sanitized) since we migrated from one db host to another:

Count: 1  Time=29.70s (29s)  Lock=0.00s (0s)  Rows=1.0 (1), clearspace_user[clearspace_user]@app02
  SELECT taskID, parentObjectType, parentObjectID, subject, body, userID, assignorID, ownerID, creationDate, modificationDate, dueDate, completed FROM jivePTask WHERE taskID = N

Count: 1  Time=27.91s (27s)  Lock=0.00s (0s)  Rows=1.0 (1), clearspace_user[clearspace_user]@app02
  SELECT COUNT(jiveSGroupMember.userID) FROM jiveUser, jiveSGroupMember WHERE N=N AND jiveSGroupMember.userID = jiveUser.userID  AND jiveSGroupMember.groupID = N AND (  jiveSGroupMember.memberType = N )  AND jiveSGroupMember.userID = N

Count: 1  Time=26.30s (26s)  Lock=0.00s (0s)  Rows=0.0 (0), clearspace_user[clearspace_user]@app02
  UPDATE jivePTask SET subject = 'S', body = 'S', assignorID = N, ownerID = N, modificationDate = N, dueDate = N, dueDateNull = N, completed = N WHERE taskID = N

Count: 1  Time=26.09s (26s)  Lock=0.00s (0s)  Rows=0.0 (0), clearspace_user[clearspace_user]@app02
  INSERT INTO jiveWidgetFrmProp (frameID, name, propValue) VALUES (N,'S','S')

Count: 3  Time=24.73s (74s)  Lock=0.00s (0s)  Rows=0.7 (2), clearspace_user[clearspace_user]@2hosts
  SELECT userID, username, passwordHash, name, firstName, lastName, nameVisible, email, emailVisible, userEnabled, creationDate, modificationDate, lastLoggedIn, email, isExternal, federated, status FROM jiveUser WHERE username='S'

Count: 3  Time=24.55s (73s)  Lock=0.00s (0s)  Rows=0.0 (0), clearspace_user[clearspace_user]@app02
  UPDATE jiveProperty SET propValue='S' WHERE name='S'

Count: 1  Time=24.16s (24s)  Lock=0.00s (0s)  Rows=5.0 (5), clearspace_user[clearspace_user]@app02
  SELECT statValue, statDate FROM jiveStat WHERE statID = N AND communityID = N AND statDate >= N AND statDate <= N

Count: 1  Time=23.96s (23s)  Lock=0.00s (0s)  Rows=0.0 (0), wordpressmu_user[wordpressmu_user]@www02
  UPDATE wp_281_posts SET `post_author` = 'S', `post_date` = 'S', `post_date_gmt` = 'S', `post_content` = 'S', `post_content_filtered` = 'S', `post_title` = 'S', `post_excerpt` = 'S', `post_status` = 'S', `post_type` = 'S', `comment_status` = 'S', `ping_status` = 'S', `post_password` = 'S', `post_name` = 'S', `to_ping` = 'S', `pinged` = 'S', `post_modified` = 'S', `post_modified_gmt` = 'S', `post_parent` = 'S', `menu_order` = 'S', `guid` = 'S' WHERE ID = 'S'

Count: 1  Time=22.74s (22s)  Lock=0.00s (0s)  Rows=1.0 (1), clearspace_user[clearspace_user]@app02
  SELECT internalDocID, typeID FROM jiveDocument WHERE documentID='S'

Count: 4  Time=22.36s (89s)  Lock=0.00s (0s)  Rows=1.0 (4), clearspace_user[clearspace_user]@2hosts
  SELECT id FROM jiveID WHERE idType=N

If you need some sample queries run, I can now do that myself.

I'll be working w/ the dba's a bit more; my concern though is w/ the counts; none of these has a particularly high occurence rate (if I'm interpreting the report accurately).

To put this in scale, in the past two weeks, we've had 1700+ requests to /clearspace/index.jspa that have taken longer than 10s to complete.

I'll continue to work w/ the DBA's to get a broader picture of db performance, but right now, I'm viewing these as outliers.

Can you provide what queries you'd like to ensure are functioning within a given range?  I can then run some ad-hoc testing of these manually, in addition to the reports from the dba's.

Thanks,

--Bret

Our whole slow query log is a bit oversized (many gigs, dba's owe me some log rotation ), but the following seem to be the most likely candidates:

# Query 11: 8.40 QPS, 0.00x concurrency, ID 0x939EE24E862D3EE8 at byte 10746215707
# This item is included in the report because it matches --limit.
#              pct   total     min     max     avg     95%  stddev  median
# Count          0      64
# Exec time      1   1259s      2s     52s     20s     35s     25s      6s
# Lock time      0     5ms    36us   163us    71us   138us    26us    54us
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      0       0       0       0       0       0       0       0
# Users          1 clearspace_user
# Databases      1 clearspace
# Time range 2009-02-10 12:52:29 to 2009-03-26 15:32:31
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ###########################################
#  10s+  ################################################################
UPDATE jiveUser SET name='XXX', firstName=null, lastName=null, nameVisible=1, email='XXX', emailVisible=1, passwordHash='XXX', userEnabled = 1, creationDate=1235626296657, modificationDate=1236813631789, lastLoggedIn = 1236813631789, username = 'XXX', isExternal=0, federated=1, status = 6 WHERE userID=3469\G

# Query 19: 6.56 QPS, 0.00x concurrency, ID 0x5D077CA4494210DD at byte 10746215389
# This item is included in the report because it matches --limit.
#              pct   total     min     max     avg     95%  stddev  median
# Count          0      29
# Exec time      0    443s      2s     54s     15s     32s     10s      7s
# Lock time      0     1ms    26us    45us    35us    38us     9us    33us
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      0       0       0       0       0       0       0       0
# Users          1 clearspace_user
# Databases      1 clearspace
# Time range 2009-01-28 19:25:44 to 2009-03-26 07:43:38
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+  ###########################################################
UPDATE jiveID SET id = id + 1 WHERE idType=310 AND ((@updatedId := id) IS NULL OR (@updatedId := id) IS NOT NULL)\G

# Query 21: 7.57 QPS, 0.00x concurrency, ID 0x89B06AEF35066F71 at byte 10746214552
# This item is included in the report because it matches --outliers.
#              pct   total     min     max     avg     95%  stddev  median
# Count          0      18
# Exec time      0    328s      2s     58s     18s     32s     12s     13s
# Lock time      0   718us    20us   223us    39us    40us     7us    26us
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      0       0       0       0       0       0       0       0
# Users          1 clearspace_user
# Databases      0
# Time range 2009-01-30 11:47:41 to 2009-03-20 10:48:20
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ########################################
#  10s+  ################################################################
DELETE FROM jiveDraftProp WHERE draftID = 19484\G

# Query 22: 6.55 QPS, 0.00x concurrency, ID 0x49A9C85C3F016806 at byte 4183439444
# This item is included in the report because it matches --outliers.
#              pct   total     min     max     avg     95%  stddev  median
# Count          0      31
# Exec time      0    310s   398ms    199s     10s      5s      3s      4s
# Lock time      0     2ms    16us   118us    51us    84us    17us    47us
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      0       0       0       0       0       0       0       0
# Users          1 clearspace_user
# Databases      0
# Time range 2009-01-26 22:03:14 to 2009-03-24 12:12:41
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ############
#    1s  ################################################################
#  10s+  ##
DELETE FROM jiveStat WHERE communityID = 2315\G

# Query 23: 6.86 QPS, 0.00x concurrency, ID 0x76D871A02A425819 at byte 9237182593
# This item is included in the report because it matches --outliers.
#              pct   total     min     max     avg     95%  stddev  median
# Count          0      16
# Exec time      0    160s      2s     31s     10s     26s      6s      7s
# Lock time      0   682us    21us    66us    42us    60us    11us    44us
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      0       0       0       0       0       0       0       0
# Users          1 clearspace_user
# Databases      1 clearspace
# Time range 2009-01-28 09:25:41 to 2009-03-23 09:25:10
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+  #############################
UPDATE jiveViewCount SET viewCount=127 WHERE objectType=102 AND objectID=18202\G

# Query 24: 15.42 QPS, 0.00x concurrency, ID 0x9912D8641A81158E at byte 3524340157
# This item is included in the report because it matches --outliers.
#              pct   total     min     max     avg     95%  stddev  median
# Count          0      23
# Exec time      0     80s      2s      8s      3s      5s      2s      3s
# Lock time      0   472us    14us    31us    20us    27us     2us    19us
# Rows sent      0       0       0       0       0       0       0       0
# Rows exam      0       0       0       0       0       0       0       0
# Users          1 clearspace_user
# Databases      1 clearspace
# Time range 2009-02-11 02:09:36 to 2009-03-07 02:31:24
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
INSERT INTO jiveStat(statID,communityID,statDate,statValue) VALUES(303,2908,1234414800000,0.0)\G

(Full log attached.)

I'll be doing some more analysis on a smaller slice of data, trying to tie the slow queries up w/ the access log render times.

I've engaged our DBAs, moving this to waiting on me until we hear back from them.

I've gotten some feedback from the DBA's; we're still seeing some issues crop up in our slow queries log.  I've listed them below, w/ the corresponding explain plan from our stage env:

> Count: 2  Time=25.21s (50s)  Lock=0.00s (0s)  Rows=0.0 (0), xxx[xxx]@2hosts
>   UPDATE jiveViewCount SET viewCount=N WHERE objectType=N AND objectID=N

mysql> EXPLAIN EXTENDED select  viewCount=127 from jiveViewCount where  objectType=102 AND objectID=2024;
+----+-------------+---------------+-------+---------------+---------+---------+-------------+------+----------+-------+
| id | select_type | table         | type  | possible_keys | key     | key_len | ref         | rows | filtered | Extra |
+----+-------------+---------------+-------+---------------+---------+---------+-------------+------+----------+-------+
|  1 | SIMPLE      | jiveViewCount | const | PRIMARY       | PRIMARY | 12      | const,const |    1 |   100.00 |       |
+----+-------------+---------------+-------+---------------+---------+---------+-------------+------+----------+-------+


> Count: 6  Time=23.82s (142s)  Lock=0.00s (0s)  Rows=0.0 (0), xxx[xx]@app01
>   UPDATE jiveUser SET name='S', firstName=null, lastName=null, nameVisible=N, email='S', emailVisible=N, passwordHash='S', userEnabled = N, creationDate=N, modificationDate=N, lastLoggedIn = N, username = 'S', isExternal=N, federated=N, status = N WHERE userID=N

mysql> EXPLAIN EXTENDED select  name, firstName, lastName, nameVisible, email, emailVisible, passwordHash, userEnabled, creationDate, modificationDate, lastLoggedIn, username, isExternal, federated, status from jiveUser where   userID=3000;
+----+-------------+----------+-------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table    | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+----------+-------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | jiveUser | const | PRIMARY       | PRIMARY | 8       | const |    1 |   100.00 |       |
+----+-------------+----------+-------+---------------+---------+---------+-------+------+----------+-------+


> Count: 1  Time=21.85s (21s)  Lock=0.00s (0s)  Rows=1.0 (1), xxx[xxx]@app01
>   SELECT bodyData FROM jiveDocumentBody WHERE bodyID=N

mysql> explain extended SELECT bodyData FROM jiveDocumentBody WHERE bodyID=20527;
+----+-------------+------------------+-------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table            | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+------------------+-------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | jiveDocumentBody | const | PRIMARY       | PRIMARY | 8       | const |    1 |   100.00 |       |
+----+-------------+------------------+-------+---------------+---------+---------+-------+------+----------+-------+


> Count: 3  Time=20.38s (61s)  Lock=0.00s (0s)  Rows=0.0 (0), xxx[xxx]@2hosts
>   UPDATE jiveID SET id = id + N WHERE idType=N AND ((@updatedId := id) IS NULL OR (@updatedId := id) IS NOT NULL)

Er, skip, weird syntax :)


> Count: 1  Time=15.80s (15s)  Lock=0.00s (0s)  Rows=0.0 (0), xxx[xxx]@app01
>   SELECT draftID, userID, draftType, objectType, objectID, subject, body, modificationDate FROM jiveDraft WHERE userID=N AND draftType = N AND objectType = N AND objectID = N

mysql> EXPLAIN EXTENDED select * from  jiveDraftProp WHERE draftID = 19484;
+----+-------------+---------------+------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table         | type | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+---------------+------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | jiveDraftProp | ref  | PRIMARY       | PRIMARY | 8       | const |    1 |   100.00 |       |
+----+-------------+---------------+------+---------------+---------+---------+-------+------+----------+-------+


> Count: 2  Time=14.48s (28s)  Lock=0.00s (0s)  Rows=1.0 (2), xxx[xxx]@2hosts
>   SELECT count(*) FROM jiveID

mysql> explain extended select count(*) from jiveID;
+----+-------------+--------+-------+---------------+---------+---------+------+------+----------+-------------+
| id | select_type | table  | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |
+----+-------------+--------+-------+---------------+---------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | jiveID | index | NULL          | PRIMARY | 4       | NULL |   57 |   100.00 | Using index |
+----+-------------+--------+-------+---------------+---------+---------+------+------+----------+-------------+


> Count: 1  Time=8.64s (8s)  Lock=0.00s (0s)  Rows=0.0 (0), xxx[xxx]@app01
>   DELETE FROM jiveDraftProp WHERE draftID = N

mysql> EXPLAIN EXTENDED select * from  jiveDraftProp WHERE draftID = 19484;
+----+-------------+---------------+------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table         | type | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+---------------+------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | jiveDraftProp | ref  | PRIMARY       | PRIMARY | 8       | const |    1 |   100.00 |       |
+----+-------------+---------------+------+---------------+---------+---------+-------+------+----------+-------+

Several requests yesterday took 100s+ to finish; I don't have full tally yet, or the ratio of slow requests to slow queries yet.

The selects run quite fast against the db.  What we're seeing in the slow query logs is periodic slowness based upon mostly updates and deletes.

No.

The box is pretty much idle.  DBAs are looking into a theory around getting mysql to tell us when it's doing some of its internal log rotations to see if that's related; but recent slow-query-log entries have only been on the order of 30'ish seconds, tops.  Apache request times are much, much worse.  Graphs to come.

Nope:  MySQL             5.1.26-rc-community-log , though we'll be upgrading to 5.1.30 very soon.

MySQL-AB JDBC Driver mysql-connector-java-5.0.7 ( $Date: 2007-03-09 22:13:57 +0100 (Fri, 09 Mar 2007) $, $Revision: 6341 $ )\

I'm becoming less convinced that the db is the biggest problem re: performance.  While the 30s+ times are sucky, they're a drop in the bucket, and don't correspond well to the worst request times.  I've attached a graph of the two.

Austen,

1. Can you provide a bit more clarity on why you think item #1 might help?  The only environment experiencing this issue is our production one, and changing something like that is non-trivial for us.  I need a bit more details before I can submit that RFC.
2. What makes you think mod_jk might be at fault?  We may be able to remove this from the stack, provided that our container will support REMOTE_USER via the http/s connectors; but again, I'd like to understand why you think this may be the issue.

--Bret

I'm closing this case at this point, we seem to have found the major performance stumbling block:  mod_jk.

When we updated to mod_jk/1.2.28 on RHEL 5, that seems to have had a pretty massive performance improvement.

If there are subsequent performance issues, I'll open a new, more targeted ticket.

Many thanks to both you and Erik for working w/ us on this gnarled issue.