Saving entries takes extremely long (up to eight minutes)

[mikko]

Running SugarCRM 5.0.0a community edition on a *nix Box with PHP 5.2.0 and Apache 2.2.3 and connecting to a dedicated MySQL box, also *nix, with MySQL 5.0.32 installed. PHP's MySQL client on the Sugar server is 5.0.32 as well.

From time to time (sometimes all the time), saving entries takes from four to eight minutes. I've checked system load, mysql connections, connection speed, slow queries, query cache size etc and it all checks out. Usually, when Sugar gets stuck, my stats show that I'm using maybe one or two MySQL connections (out of 250), the cache is 90% unused, running threads is at 2 or 3 and slow queries is at zero.

Also system load is about zero, as well as running apache processes (anyway none on the DB server, the Sugar server has maybe one or two apache processes running, both under 1% cpu usage.

When I check the mysql process list while Sugar gets stuck, it shows something like:

mysql> SHOW FULL PROCESSLIST;
+-------+----------+------------------------------------+----------+---------+------+-------+-----------------------+
| Id    | User     | Host                               | db       | Command | Time | State | Info                  |
+-------+----------+------------------------------------+----------+---------+------+-------+-----------------------+
| 20739 | sugarcrm | umv-web-03.#################:55387 | sugarcrm | Sleep   |  214 |       | NULL                  | 
| 20747 | dwh      | ############:4265                  | dwh      | Sleep   |    0 |       | NULL                  | 
| 20758 | root     | localhost                          | NULL     | Query   |    0 | NULL  | SHOW FULL PROCESSLIST | 
+-------+----------+------------------------------------+----------+---------+------+-------+-----------------------+
3 rows in set (0.00 sec)

...so obviously, Sugar is not closing the database connection (even though it isn't actually doing anything).

I've tried setting 'dbconfigoption' => 'persistent' to false, among with a few other speedup optimisations found in the wiki, but it doesn't seem to have any effect.

The network between the two servers is not the bottleneck, they're both in the same rack and connected to the same gigabit switch. I've also made sure that they're the only two servers using the network at the time of testing...

The issue is quite odd, I'm using less than 1% of the capacity of my systems and network and Sugar still gets stuck about every second time anyone tries to save anything.

Any ideas, tips, tricks? Anything else I could tweak anywhere?

[kuske]

Who is that dwh-user? Perhaps a data warehouse blocking all tables because the dwh cube is rebuild from time to time?
I had simular effects on other databases in conjunction with dwh-software.

Is it possible to stop the dwh and to reproduce your effects then?

[mikko]

Yeah, a data warehouse user. Actually, I chose that part of MySQL process list rather poorly, there was a dwh job running at the time.

About 90% of the time when this happens, though, sugarcrm is the only user on the system. I've ran several tests with all other software accessing the database server switched off and the problem keeps coming back.

And in any case, all resource-consuming dwh jobs run at night, the few selects and updates that happen during the daytime only cause a minimal impact on the system, surely nothing that a dedicated database server shouldn't be able to handle. And this hang-up happens even if there is only one mysql thread running with one connection and with one user (and only one person operating SugarCRM).

[kuske]

I would set the debugging level to "debug" (file: log4php.properties) and check the logfile for the long time save actions. Perhaps there is a hint in the logfile or at least the full sql statement which takes so log time.
So perhaps you can find a database missconfiguration.
e.g. ee had a issue here with long tax numbers without database index, so perhapos you have a simular problem.

[mikko]

Been observing the log file now for a day and as far as I can tell, the queries themselves aren't the issue here, they all run under 0.0005 seconds.

Here's what happens when I click save and Sugar gets stuck:

Wed Feb 20 11:34:19 2008,661 [22389] INFO SugarCRM - Query Execution Time:0.000552
Wed Feb 20 11:34:19 2008,959 [10895] INFO SugarCRM - Query:SELECT id, name, symbol, conversion_rate FROM currencies WHERE status = 'Active' and deleted = 0
Wed Feb 20 11:34:19 2008,960 [10895] INFO SugarCRM - Query Execution Time:0.000201
Wed Feb 20 11:34:19 2008,964 [10895] INFO SugarCRM - Query:SELECT category, name, value FROM config
Wed Feb 20 11:34:19 2008,964 [10895] INFO SugarCRM - Query Execution Time:0.000407
Wed Feb 20 11:34:19 2008,966 [10895] INFO SugarCRM - Query:SELECT id FROM outbound_email WHERE type = 'system'
Wed Feb 20 11:34:19 2008,966 [10895] INFO SugarCRM - Query Execution Time:0.000249
Wed Feb 20 11:34:19 2008,966 [10895] INFO SugarCRM - Query:SELECT * FROM outbound_email WHERE id = '5824dbc7-9349-d227-c141-47a2224c5cd9'
Wed Feb 20 11:34:19 2008,967 [10895] INFO SugarCRM - Query Execution Time:0.000255

After which, a five minute pause occurs. MySQL process list shows the process state as SLEEP and the page just continues loading. After about five minutes, the logs proceed with:

Wed Feb 20 11:39:19 2008,681 [10895] DEBUG SugarCRM - We have an authenticated user id: 1
Wed Feb 20 11:39:19 2008,681 [10895] DEBUG SugarCRM - Retrieve User : SELECT users.* FROM users  WHERE users.id = '1'  AND users.deleted=0
Wed Feb 20 11:39:19 2008,682 [10895] DEBUG SugarCRM - Limit Query:SELECT users.* FROM users  WHERE users.id = '1'  AND users.deleted=0 Start: 0 count: 1
Wed Feb 20 11:39:19 2008,682 [10895] INFO SugarCRM - Query:SELECT users.* FROM users  WHERE users.id = '1'  AND users.deleted=0 LIMIT 0,1
Wed Feb 20 11:39:19 2008,684 [10895] INFO SugarCRM - Query Execution Time:0.001544

...and so on, followed by the actual queries that save the entry.

As far as I can tell, it gets always stuck at that same point.