Slow Queries

[Migrated From Jforum.net]

Ok, I have investigated a lot more as to what is going on with the forums slow response and performance issues.

There is a serious problem with the search function as it times out connections big time. Here is a glimpse of the slow queries...

UPDATE jforum_topics_watch SET is_read = 1 WHERE topic_id = 2577 AND user_id = 8181;
# Time: 050718 19:45:49
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 25 Lock_time: 0 Rows_sent: 1673 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('after');
# Time: 050718 19:45:58
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 3 Lock_time: 0 Rows_sent: 43 Rows_examined: 10310
SELECT COUNT(pm.privmsgs_to_userid) AS private_messages, u.* FROM jforum_users u LEFT JOIN jforum_privmsgs pm ON pm.privmsgs_type = 1 AND pm.privmsgs_to_userid = u.user_id WHERE u.user_id = 7421 GROUP BY pm.privmsgs_to_userid;
# Time: 050718 19:46:03
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 25 Lock_time: 0 Rows_sent: 0 Rows_examined: 3076542
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('gurl/guy');
# Time: 050718 19:46:04
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 23 Lock_time: 0 Rows_sent: 1673 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('after');
# Time: 050718 19:46:12
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 23 Lock_time: 0 Rows_sent: 0 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('a');
# Time: 050718 19:46:15
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 3 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('after');
# Time: 050718 19:46:28
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 23 Lock_time: 0 Rows_sent: 0 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('a');
# Time: 050718 19:46:31
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 31 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_topics SET topic_views = topic_views + 1 WHERE topic_id = 2798;
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 33 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_topics_watch SET is_read = 1 WHERE topic_id = 2802 AND user_id = 6788;
# Time: 050718 19:46:36
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 31 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_topics_watch SET is_read = 1 WHERE topic_id = 2577 AND user_id = 8181;
# Time: 050718 19:46:37
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 4 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('one');
# Time: 050718 19:46:42
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 13 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
INSERT INTO jforum_sessions ( session_id, session_user_id, session_start ) VALUES ('B65F302751D859E584206780B17128B1', 11094, '2005-07-18 19:25:19');
# Time: 050718 19:46:50
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 23 Lock_time: 0 Rows_sent: 0 Rows_examined: 3076542
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('a');
# Time: 050718 19:46:51
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 23 Lock_time: 0 Rows_sent: 6726 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('one');
# Time: 050718 19:46:55
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 26 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_topics SET topic_views = topic_views + 1 WHERE topic_id = 2798;
# Time: 050718 19:47:00
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 40 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_sessions SET session_start = '2005-07-18 19:20:43', session_time = 266859, session_id = 'A6729DC4218EBF5263983EAD966BF420' WHERE session_user_id = 4142;
# Time: 050718 19:47:01
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 24 Lock_time: 0 Rows_sent: 954 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('night');
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 18 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_sessions SET session_start = '2005-07-18 19:25:06', session_time = 8547, session_id = 'ECAC7070A4A8C7FB57D32F51644BE6C2' WHERE session_user_id = 1480;
# Time: 050718 19:47:15
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 24 Lock_time: 0 Rows_sent: 6726 Rows_examined: 3076542
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('one');
# Time: 050718 19:47:22
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 24 Lock_time: 0 Rows_sent: 954 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('night');
# Time: 050718 19:47:25
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 24 Lock_time: 0 Rows_sent: 1 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('stand?\"');
# Time: 050718 19:47:32
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 31 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
INSERT INTO jforum_sessions ( session_id, session_user_id, session_start ) VALUES ('B9CAFD5FED449DF798621F89BDD9B0B5', 11095, '2005-07-18 19:26:30');
# Time: 050718 19:47:36
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 21 Lock_time: 0 Rows_sent: 954 Rows_examined: 3076542
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('night');
# Time: 050718 19:47:41
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 19 Lock_time: 0 Rows_sent: 76 Rows_examined: 3076476
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('stand?');
# Time: 050718 19:47:49
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 13 Lock_time: 0 Rows_sent: 76 Rows_examined: 3076542
SELECT post_id FROM jforum_search_wordmatch wm, jforum_search_words w WHERE wm.word_id = w.word_id AND LOWER(w.word) = LOWER('stand?');
# Time: 050718 19:49:03
# User@Host: db[db] @ localhost [127.0.0.1]
# Query_time: 31 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
UPDATE jforum_sessions SET session_start = '2005-07-18 19:27:46', session_time = 344, session_id = 'D29B79B6789497FEDA6C0AA067758D05' WHERE session_user_id = 5660;
MySql, Version: 4.1.12a-nt-max-log. started with:
TCP Port: 3306, Named Pipe: /tmp/mysql.sock
Time Id Command Argument

Keep in mind this is a dual xeon.

Brakker

[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Yes, the search is going bad. I have a forum with 150.00 messages and the search is killing the system.

I'm investigating it. For now, you can disable search by hand (aka, remove "search" from WEB-INF/config/modulesMapping.properties)

Rafael
[originally posted on jforum.net by Rafael Steil]

[Migrated From Jforum.net]

Ok, bug fixed. You can get generic_queries.sql and GenericSearchIndexerDAO.java from the CVS.

The problem is that I was using LOWER(field) = LOWER('search'), and this was causing mysql to ignore indexes.

Rafael
[originally posted on jforum.net by Rafael Steil]

[Migrated From Jforum.net]

Nice Job.

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Rafael,

I was getting this error in the search before the fix and now after too..


An error has ocurred. For detailed stack trace, please see the page's source code.
Data truncation: Data truncated for column 'topic_title' at row 1



:577)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadP
ool.java:683)
at java.lang.Thread.run(Thread.java:534)
Caused by: com.mysql.jdbc.MysqlDataTruncation: Data truncation: Data truncated f
or column 'topic_title' at row 1
at com.mysql.jdbc.SQLError.convertShowWarningsToSQLWarnings(SQLError.jav
a:693)
at com.mysql.jdbc.MysqlIO.scanForAndThrowDataTruncation(MysqlIO.java:328
6)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:1728)
at com.mysql.jdbc.Connection.execSQL(Connection.java:2234)
at com.mysql.jdbc.Connection.execSQL(Connection.java:2159)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.ja
va:1802)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java
:1896)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java
:1821)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java
:1683)
at net.jforum.dao.generic.GenericSearchDAO.selectTopicData(GenericSearch
DAO.java:221)
at net.jforum.dao.generic.GenericSearchDAO.topicsByKeyword(GenericSearch
DAO.java:211)
at net.jforum.dao.generic.GenericSearchDAO.search(GenericSearchDAO.java:
79)
at net.jforum.view.forum.SearchAction.search(SearchAction.java:182)
... 33 more

Any ideas?

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Yes, I do have an ideia ;)

Run this statement:

ALTER TABLE jforum_search_topics CHANGE topic_title topic_title VARCHAR(100);

The file mysql_db_structl.sql from 2.1.4+ is correct, but I guess the files used by the installer are not, so that's why you have the field created as VARCHAR(60) yet.

Rafael
[originally posted on jforum.net by Rafael Steil]

[Migrated From Jforum.net]

Thanks, the search seems to be working much better now.

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Great!!

Btw, I saw the number of anonymous online users is very big in your forum. Aren't you using the ClickstreamFilter?

Rafael
[originally posted on jforum.net by Rafael Steil]

[Migrated From Jforum.net]

Yes, I saw that. It's very strange because the old version without clickstream never showed that many users online. I do not understand why that is happening because clickstream is on by default.

Also, for some reason, the new version is very processor intensive compared to the old version.

Couple of slow queries still, but these aren't causing any major problems I don't think...


UPDATE jforum_sessions SET session_start = '2005-07-19 19:05:31', session_time = 47281, session_id = 'AF4856CA6191FF47E960B2E95266358C' WHERE session_user_id = 8696;

UPDATE jforum_topics SET topic_views = topic_views + 1 WHERE topic_id = 572;


Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

The only thing I can think of in terms of the anonymous users is that there was a major coincidence in that the forums got index by search engines at the same time that I switched to the new version.

That does seem like one heck of a coincidence though. Unfortunately, all logs are off so I cannot see the referrers.

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

brakker wrote: I do not understand why that is happening because clickstream is on by default.

Just to confirm: did you put

<filter>
	<filter-name>clickstream-jforum</filter-name>
	<filter-class>net.jforum.util.legacy.clickstream.ClickstreamFilter</filter-class>
</filter>

<filter-mapping>
	<filter-name>clickstream-jforum</filter-name>
	<url-pattern>*.page</url-pattern>
</filter-mapping>
    

in your web.xml? I ask that because I forgot to add to one of my websites after an upgrade

brakker wrote:


UPDATE jforum_sessions SET session_start = '2005-07-19 19:05:31', session_time = 47281, session_id = 'AF4856CA6191FF47E960B2E95266358C' WHERE session_user_id = 8696;

UPDATE jforum_topics SET topic_views = topic_views + 1 WHERE topic_id = 572;

Well, the update to jforum_sessions is supposed to only happen when the user's session expires. On the other hand, the topic_views occurs on each view, but this exists since the first beta version.

I can't remember right now every change I've made to version 2.1.5, but, anyway, nothing of so much different comes to my mind. There ist he ClickstreamFilter, that only lookups a Map instance.

I was expecting to get much more performance, but looks like the opposite is happening .

Rafael
[originally posted on jforum.net by Rafael Steil]

[Migrated From Jforum.net]

Yeah, my web.xml does have the clickstream tags in it. I know it's working because I see the output in the consol when bots are hitting the site. It's strange...seems like the number of guests just keeps rising...it's up to 1750 at 3AM...definitely some kind of issue there.

As for the update to jforum_sessions, the table just needed an index on session_user_id...was missing for some reason. Maybe you didn't think an index was necessary as the records for this table should only be as large as the number of people online? Well, I have over 11,000 records in this table so maybe they aren't getting cleaned or something. I put the index in and that query is now much faster.

What I really don't understand is that the following updates take up to 4-5 seconds:

UPDATE jforum_topics SET topic_views = topic_views + 1 WHERE topic_id = ?;
and
UPDATE jforum_topics SET topic_title = ?, topic_last_post_id = ?, topic_first_post_id = ?, topic_type = ?, moderated =? WHERE topic_id = ?;
and
UPDATE jforum_topics_watch SET is_read = ? WHERE topic_id = ? AND user_id = ?;

These updates should not be showing up under the slow query log. All of them seem to be taking an average of 4-12 seconds. I tried restoring the index/primary key and that didn't help any.

Outside of these queries, the number of guest users online and the performance hit somewhere in the code, everything really seems to be working well. I know these issues are not big ones as they will just take a little tracking down. I will do my best to see if I can find more answers tomorrow (well today).

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Rafael,

I just investigated the anonymous user sessions. Basically, for every user that gets logged in, if you look in the service method in JForum, there is the code:

ControllerUtils utils = new ControllerUtils();
utils.refreshSession();

The refrshSession is causing an anonymous user session to be added to cache every time there is a registered user session. Without looking further into this, I am assuming that once the actual user session is created, it is overriding the anonymous session which is causing the anonymous session to stay in cache.

What would you suggest to do with this?

Beyond that, today I am going to try and look into the performance bottleneck some more.

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Ok, nevermind.

Because I had to write the login authentication specific for my app, I forgot to add your line that removes the guest session. I will add that back and I am sure that will fix it.

Brakker
[originally posted on jforum.net by coolbreeze]

[Migrated From Jforum.net]

Rafael,

In regards to performance issues, I don't see anything that stands out except the way the jvm gc. I now think the gc is what is causing my processor to spike to double the usage. I believe it's this incremental gc that is causing it. If you have a somewhat busy system, you can test for similar results by using these jvm startup params:

-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -XX:+CMSPermGenSweepingEnabled -XX:+UseConcMarkSweepGC -XX:+CMSClassUnloadingEnabled -XX:PermSize=300m -Xms1000m -Xmx1000m

You obviously can set the amount of memory to whatever as those are just my needed params at the moment. This has to be what is causing the spikes in processor. Basically, in my gc setup here, I have threaded class unloading enabled and the incremental gc. I think that most of the processor spikes I am seeing are coming from the threaded class unloading, although I haven't taken it out yet because of it being on a production system. I have to say that the threaded class unloading definitely helps to unblock the gc making its rounds as the system flows very fluid like. If it weren't for the processor spikes, I would leave all alone as everything is running very smoothly.

Brakker
[originally posted on jforum.net by coolbreeze]